Skip to content

Commit 738997b

Browse files
FabianEckermannFabianEckermann
committed
cu_cp,ngap: Improve logging
1 parent 94271d7 commit 738997b

File tree

1 file changed

+80
-35
lines changed

1 file changed

+80
-35
lines changed

‎lib/ngap/ngap_impl.cpp‎

Lines changed: 80 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -56,11 +56,11 @@ void ngap_impl::create_ngap_ue(ue_index_t ue_index,
5656
ngap_ue* ue = ue_manager.add_ue(ue_index, rrc_ue_pdu_notifier, rrc_ue_ctrl_notifier, du_processor_ctrl_notifier);
5757

5858
if (ue == nullptr) {
59-
logger.error("ue={} Failed to create UE", ue_index);
59+
logger.error("ue={}: Failed to create UE", ue_index);
6060
return;
6161
}
6262

63-
logger.debug("ue={} Created UE (ran_ue_id={})", ue_index, ue->get_ran_ue_id());
63+
logger.debug("ue={} ran_ue_id={}: Created UE", ue_index, ue->get_ran_ue_id());
6464
}
6565

6666
async_task<ng_setup_response> ngap_impl::handle_ng_setup_request(const ng_setup_request& request)
@@ -74,7 +74,7 @@ void ngap_impl::handle_initial_ue_message(const ngap_initial_ue_message& msg)
7474
{
7575
auto* ue = ue_manager.find_ngap_ue(msg.ue_index);
7676
if (ue == nullptr) {
77-
logger.warning("ue={} does not exist - dropping InitialUeMessage", msg.ue_index);
77+
logger.warning("ue={}: Dropping InitialUeMessage. UE does not exist", msg.ue_index);
7878
return;
7979
}
8080

@@ -107,7 +107,7 @@ void ngap_impl::handle_initial_ue_message(const ngap_initial_ue_message& msg)
107107

108108
// TODO: Add missing optional values
109109

110-
logger.info("ue={} Sending InitialUeMessage (ran_ue_id={})", msg.ue_index, ue->get_ran_ue_id());
110+
logger.info("ue={} ran_ue_id={}: Sending InitialUeMessage", msg.ue_index, ue->get_ran_ue_id());
111111

112112
// Forward message to AMF
113113
ngap_notifier.on_new_message(ngap_msg);
@@ -117,7 +117,7 @@ void ngap_impl::handle_ul_nas_transport_message(const ngap_ul_nas_transport_mess
117117
{
118118
auto* ue = ue_manager.find_ngap_ue(msg.ue_index);
119119
if (ue == nullptr) {
120-
logger.warning("ue={} does not exist - dropping UlNasTransportMessage", msg.ue_index);
120+
logger.warning("ue={}: Dropping UlNasTransportMessage. UE does not exist", msg.ue_index);
121121
return;
122122
}
123123

@@ -131,7 +131,7 @@ void ngap_impl::handle_ul_nas_transport_message(const ngap_ul_nas_transport_mess
131131

132132
amf_ue_id_t amf_ue_id = ue->get_amf_ue_id();
133133
if (amf_ue_id == amf_ue_id_t::invalid) {
134-
logger.warning("ue={} UE AMF ID not found!", msg.ue_index);
134+
logger.warning("ue={}: UE AMF ID not found", msg.ue_index);
135135
return;
136136
}
137137
ul_nas_transport_msg->amf_ue_ngap_id = amf_ue_id_to_uint(amf_ue_id);
@@ -144,7 +144,10 @@ void ngap_impl::handle_ul_nas_transport_message(const ngap_ul_nas_transport_mess
144144
user_loc_info_nr.tai.plmn_id = msg.nr_cgi.plmn_id;
145145
user_loc_info_nr.tai.tac.from_number(msg.tac);
146146

147-
logger.info("ue={} Sending UlNasTransportMessage (ran_ue_id={})", msg.ue_index, ue->get_ran_ue_id());
147+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Sending UlNasTransportMessage",
148+
msg.ue_index,
149+
ue->get_ran_ue_id(),
150+
ue->get_amf_ue_id());
148151

149152
// Forward message to AMF
150153
ngap_notifier.on_new_message(ngap_msg);
@@ -218,22 +221,30 @@ void ngap_impl::handle_dl_nas_transport_message(const asn1::ngap::dl_nas_transpo
218221
{
219222
ue_index_t ue_index = ue_manager.get_ue_index(uint_to_ran_ue_id(msg->ran_ue_ngap_id));
220223
if (ue_index == ue_index_t::invalid) {
221-
logger.warning("ue={} does not exist - dropping PDU", ue_index);
224+
logger.warning("ue={} ran_ue_id={} amf_ue_id={}: Dropping DlNasTransportMessage. UE does not exist",
225+
ue_index,
226+
msg->ran_ue_ngap_id,
227+
msg->amf_ue_ngap_id);
222228
return;
223229
}
224230

225231
auto* ue = ue_manager.find_ngap_ue(ue_index);
226232
if (ue == nullptr) {
227-
logger.warning("ue={} does not exist - dropping PDU", ue_index);
233+
logger.warning("ue={} ran_ue_id={} amf_ue_id={}: Dropping PDU. UE does not exist",
234+
ue_index,
235+
msg->ran_ue_ngap_id,
236+
msg->amf_ue_ngap_id);
228237
return;
229238
}
230239

231-
logger.info("ue={} Received DlNasTransportMessage (ran_ue_id={})", ue_index, ue->get_ran_ue_id());
240+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Received DlNasTransportMessage",
241+
ue_index,
242+
ue->get_ran_ue_id(),
243+
uint_to_amf_ue_id(msg->amf_ue_ngap_id));
232244

233245
// Add AMF UE ID to ue ngap context if it is not set (this is the first DL NAS Transport message)
234246
if (ue->get_amf_ue_id() == amf_ue_id_t::invalid) {
235247
// Set AMF UE ID in the UE context and also in the lookup
236-
logger.debug("ue={} Received AMF UE ID={}", ue_index, uint_to_amf_ue_id(msg->amf_ue_ngap_id));
237248
ue_manager.set_amf_ue_id(ue_index, uint_to_amf_ue_id(msg->amf_ue_ngap_id));
238249
}
239250

@@ -250,11 +261,14 @@ void ngap_impl::handle_initial_context_setup_request(const asn1::ngap::init_cont
250261
ue_index_t ue_index = ue_manager.get_ue_index(uint_to_ran_ue_id(request->ran_ue_ngap_id));
251262
auto* ue = ue_manager.find_ngap_ue(ue_index);
252263
if (ue == nullptr) {
253-
logger.warning("ue={} does not exist - dropping InitialContextSetupRequest", ue_index);
264+
logger.warning("ue={}: Dropping InitialContextSetupRequest. UE does not exist", ue_index);
254265
return;
255266
}
256267

257-
logger.info("ue={} Received InitialContextSetupRequest (ran_ue_id={})", ue_index, ue->get_ran_ue_id());
268+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Received InitialContextSetupRequest",
269+
ue_index,
270+
ue->get_ran_ue_id(),
271+
ue->get_amf_ue_id());
258272

259273
// Update AMF ID and use the one from this Context Setup as per TS 38.413 v16.2 page 38
260274
ue_manager.set_amf_ue_id(ue_index, uint_to_amf_ue_id(request->amf_ue_ngap_id));
@@ -270,7 +284,7 @@ void ngap_impl::handle_pdu_session_resource_setup_request(const asn1::ngap::pdu_
270284
ue_index_t ue_index = ue_manager.get_ue_index(uint_to_ran_ue_id(request->ran_ue_ngap_id));
271285
ngap_ue* ue = ue_manager.find_ngap_ue(ue_index);
272286
if (ue == nullptr) {
273-
logger.warning("ue={} does not exist - dropping PduSessionResourceSetupRequest (ran_ue_id={}, amf_ue_id={})",
287+
logger.warning("ue={} ran_ue_id={} amf_ue_id={}: Dropping PduSessionResourceSetupRequest. UE does not exist",
274288
ue_index,
275289
request->ran_ue_ngap_id,
276290
request->amf_ue_ngap_id);
@@ -279,14 +293,17 @@ void ngap_impl::handle_pdu_session_resource_setup_request(const asn1::ngap::pdu_
279293

280294
if (!ue->get_rrc_ue_control_notifier().on_security_enabled()) {
281295
logger.warning(
282-
"ue={} Security context does not exist - dropping PduSessionResourceSetupRequest (ran_ue_id={}, amf_ue_id={})",
296+
"ue={} ran_ue_id={} amf_ue_id={}: Dropping PduSessionResourceSetupRequest. Security context does not exist",
283297
ue_index,
284298
request->ran_ue_ngap_id,
285299
request->amf_ue_ngap_id);
286300
return;
287301
}
288302

289-
logger.info("ue={} Received PduSessionResourceSetupRequest (ran_ue_id={})", ue_index, ue->get_ran_ue_id());
303+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Received PduSessionResourceSetupRequest",
304+
ue_index,
305+
ue->get_ran_ue_id(),
306+
ue->get_amf_ue_id());
290307

291308
// Store information in UE context
292309
if (request->ue_aggr_max_bit_rate_present) {
@@ -298,7 +315,10 @@ void ngap_impl::handle_pdu_session_resource_setup_request(const asn1::ngap::pdu_
298315
msg.ue_index = ue_index;
299316
msg.serving_plmn = context.plmn;
300317
if (!fill_cu_cp_pdu_session_resource_setup_request(msg, request->pdu_session_res_setup_list_su_req)) {
301-
logger.error("ue={} Conversion of PDU Session Resource Setup Request failed.", ue_index);
318+
logger.error("ue={} ran_ue_id={} amf_ue_id={}: Conversion of PDU Session Resource Setup Request failed",
319+
ue_index,
320+
ue->get_ran_ue_id(),
321+
ue->get_amf_ue_id());
302322
return;
303323
}
304324
msg.ue_aggregate_maximum_bit_rate_dl = ue->get_aggregate_maximum_bit_rate_dl();
@@ -315,14 +335,17 @@ void ngap_impl::handle_pdu_session_resource_modify_request(const asn1::ngap::pdu
315335
ue_index_t ue_index = ue_manager.get_ue_index(uint_to_ran_ue_id(request->ran_ue_ngap_id));
316336
ngap_ue* ue = ue_manager.find_ngap_ue(ue_index);
317337
if (ue == nullptr) {
318-
logger.warning("ue={} does not exist - dropping PduSessionResourceModifyRequest (ran_ue_id={}, amf_ue_id={})",
338+
logger.warning("ue={} ran_ue_id={} amf_ue_id={}: Dropping PduSessionResourceModifyRequest. UE does not exist",
319339
ue_index,
320340
request->ran_ue_ngap_id,
321341
request->amf_ue_ngap_id);
322342
return;
323343
}
324344

325-
logger.info("ue={} Received PduSessionResourceModifyRequest (ran_ue_id={})", ue_index, ue->get_ran_ue_id());
345+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Received PduSessionResourceModifyRequest",
346+
ue_index,
347+
ue->get_ran_ue_id(),
348+
ue->get_amf_ue_id());
326349

327350
if (request->ran_paging_prio_present) {
328351
logger.debug("Not handling RAN paging prio");
@@ -344,14 +367,17 @@ void ngap_impl::handle_pdu_session_resource_release_command(const asn1::ngap::pd
344367
ue_index_t ue_index = ue_manager.get_ue_index(uint_to_ran_ue_id(command->ran_ue_ngap_id));
345368
ngap_ue* ue = ue_manager.find_ngap_ue(ue_index);
346369
if (ue == nullptr) {
347-
logger.warning("ue={} does not exist - dropping PduSessionResourceReleaseCommand (ran_ue_id={}, amf_ue_id={})",
370+
logger.warning("ue={} ran_ue_id={} amf_ue_id={}: Dropping PduSessionResourceReleaseCommand. UE does not exist",
348371
ue_index,
349372
command->ran_ue_ngap_id,
350373
command->amf_ue_ngap_id);
351374
return;
352375
}
353376

354-
logger.info("ue={} Received PduSessionResourceReleaseCommand (ran_ue_id={})", ue_index, ue->get_ran_ue_id());
377+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Received PduSessionResourceReleaseCommand",
378+
ue_index,
379+
ue->get_ran_ue_id(),
380+
ue->get_amf_ue_id());
355381

356382
// Handle optional NAS PDU
357383
if (command->nas_pdu_present) {
@@ -427,7 +453,7 @@ void ngap_impl::handle_paging(const asn1::ngap::paging_s& msg)
427453
logger.info("Received Paging");
428454

429455
if (msg->ue_paging_id.type() != asn1::ngap::ue_paging_id_c::types::five_g_s_tmsi) {
430-
logger.error("Unsupportet UE Paging ID");
456+
logger.error("Dropping PDU. Unsupportet UE Paging ID");
431457
return;
432458
}
433459

@@ -456,7 +482,7 @@ void ngap_impl::handle_ho_request(const asn1::ngap::ho_request_s& msg)
456482
// convert ho request to common type
457483
ngap_handover_request ho_request;
458484
if (!fill_ngap_handover_request(ho_request, msg)) {
459-
logger.error("Received invalid HO Request - sending Ho Failure.");
485+
logger.error("Sending HO Failure. Received invalid HO Request");
460486
ngap_notifier.on_new_message(generate_ho_fail(msg->amf_ue_ngap_id));
461487
return;
462488
}
@@ -469,12 +495,12 @@ void ngap_impl::handle_ho_request(const asn1::ngap::ho_request_s& msg)
469495
ho_request.ue_index = cu_cp_du_repository_notifier.request_new_ue_index_allocation(
470496
ho_request.source_to_target_transparent_container.target_cell_id);
471497
if (ho_request.ue_index == ue_index_t::invalid) {
472-
logger.error("Couldn't allocate UE index - sending Ho Failure");
498+
logger.error("Sending HO Failure. Couldn't allocate UE index");
473499
ngap_notifier.on_new_message(generate_ho_fail(msg->amf_ue_ngap_id));
474500
return;
475501
}
476502

477-
logger.debug("Handover request - allocated ue_index={}.", ho_request.ue_index);
503+
logger.debug("ue={}: Received HandoverRequest", ho_request.ue_index);
478504

479505
// start handover routine
480506
task_sched.schedule_async_task(
@@ -491,24 +517,34 @@ void ngap_impl::handle_error_indication(const asn1::ngap::error_ind_s& msg)
491517
{
492518
ue_index_t ue_index = ue_index_t::invalid;
493519
ngap_ue* ue = nullptr;
520+
cause_t cause;
494521
if (msg->amf_ue_ngap_id_present) {
495522
ue_index = ue_manager.get_ue_index(uint_to_amf_ue_id(msg->amf_ue_ngap_id));
496523
ue = ue_manager.find_ngap_ue(ue_index);
524+
cause = cause_radio_network_t::inconsistent_remote_ue_ngap_id;
497525
} else if (msg->ran_ue_ngap_id_present) {
498526
ue_index = ue_manager.get_ue_index(uint_to_ran_ue_id(msg->ran_ue_ngap_id));
499527
ue = ue_manager.find_ngap_ue(ue_index);
528+
cause = cause_radio_network_t::unknown_local_ue_ngap_id;
500529
}
501530

502531
if (ue == nullptr) {
503-
logger.warning("ue={} does not exist - dropping ErrorIndication", ue_index);
532+
logger.warning("ue={}{}{}: Dropping ErrorIndication. UE does not exist",
533+
ue_index,
534+
msg->ran_ue_ngap_id_present ? fmt::format(" ran_ue_id={}", msg->ran_ue_ngap_id) : "",
535+
msg->amf_ue_ngap_id_present ? fmt::format(" amf_ue_id={}", msg->amf_ue_ngap_id) : "");
504536
return;
505537
} else {
506-
std::string cause = "";
538+
std::string msg_cause = "";
507539
if (msg->cause_present) {
508-
cause = asn1_cause_to_string(msg->cause);
540+
msg_cause = asn1_cause_to_string(msg->cause);
509541
}
510542

511-
logger.info("ue={} Received ErrorIndication (ran_ue_id={}) - cause {}", ue_index, ue->get_ran_ue_id(), cause);
543+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Received ErrorIndication. Cause {}",
544+
ue_index,
545+
ue->get_ran_ue_id(),
546+
ue->get_amf_ue_id(),
547+
msg_cause);
512548
}
513549

514550
// TODO: handle error indication
@@ -546,12 +582,14 @@ void ngap_impl::handle_ue_context_release_request(const cu_cp_ue_context_release
546582
{
547583
ngap_ue* ue = ue_manager.find_ngap_ue(msg.ue_index);
548584
if (ue == nullptr) {
549-
logger.warning("ue={} does not exist - dropping UeContextReleaseRequest", msg.ue_index);
585+
logger.warning("ue={}: Dropping UeContextReleaseRequest. UE does not exist", msg.ue_index);
550586
return;
551587
}
552588

553589
if (ue->get_amf_ue_id() == amf_ue_id_t::invalid) {
554-
logger.debug("ue={} does not have an AMF UE ID - ignoring UeContextReleaseRequest.", msg.ue_index);
590+
logger.debug("ue={} ran_ue_id={}: Ignoring UeContextReleaseRequest. UE does not have an AMF UE ID",
591+
msg.ue_index,
592+
ue->get_ran_ue_id());
555593
return;
556594
}
557595

@@ -580,7 +618,10 @@ void ngap_impl::handle_ue_context_release_request(const cu_cp_ue_context_release
580618
// asn1::ngap::cause_radio_network_opts::options::user_inactivity;
581619

582620
// Forward message to AMF
583-
logger.info("ue={} Sending UeContextReleaseRequest", msg.ue_index);
621+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Sending UeContextReleaseRequest",
622+
msg.ue_index,
623+
ue->get_ran_ue_id(),
624+
ue->get_amf_ue_id());
584625
ngap_notifier.on_new_message(ngap_msg);
585626
}
586627

@@ -598,7 +639,10 @@ ngap_impl::handle_handover_preparation_request(const ngap_handover_preparation_r
598639
});
599640
}
600641

601-
logger.info("Starting HO preparation");
642+
logger.info("ue={} ran_ue_id={} amf_ue_id={}: Starting HO preparation",
643+
msg.ue_index,
644+
ue->get_ran_ue_id(),
645+
ue->get_amf_ue_id());
602646
return launch_async<ngap_handover_preparation_procedure>(msg,
603647
context,
604648
ue,
@@ -615,7 +659,7 @@ void ngap_impl::handle_inter_cu_ho_rrc_recfg_complete(const ue_index_t
615659
{
616660
auto* ue = ue_manager.find_ngap_ue(ue_index);
617661
if (ue == nullptr) {
618-
logger.warning("ue={} does not exist - dropping RrcReconfigurationComplete.", ue_index);
662+
logger.warning("ue={}: Dropping RrcReconfigurationComplete. UE does not exist", ue_index);
619663
return;
620664
}
621665

@@ -633,7 +677,8 @@ void ngap_impl::handle_inter_cu_ho_rrc_recfg_complete(const ue_index_t
633677
user_loc_info_nr.tai.tac.from_number(tac);
634678

635679
// Forward message to AMF
636-
logger.info("ue={} Sending HandoverNotify", ue_index);
680+
logger.info(
681+
"ue={} ran_ue_id={} amf_ue_id={}: Sending HandoverNotify", ue_index, ue->get_ran_ue_id(), ue->get_amf_ue_id());
637682
ngap_notifier.on_new_message(ngap_msg);
638683
}
639684

0 commit comments

Comments
 (0)