search

magma / magma

Platform for building access networks and modular network services
https://www.magmacore.org/
Other
1.66k stars 592 forks source link

Registration request of MOBILITY UPDATING REGISTRATION TYPE and Service Request not replied by AGW #15029

Open Sujay-Radtonics opened 1 year ago

Sujay-Radtonics commented 1 year ago

Your Environment

Describe the Issue

AGW is seeing a REG_REQ of type MOBILITY UPDATING REGISTRATION TYPE sometimes. But AGW is not sending any response back. After this SERVICE_REQUEST message is received on the AGW, but no response is sent to this as well. As a result UE stops working and there is continuous state of SERVICE_REQUEST and no response happening.

To Reproduce

While we are running overnight traffic, we see this issue sometimes. UE is in ACTIVE state as continuous traffic is going. Do not know what is the trigger, but once this is seen, everything stops.

Expected behavior

It is expected that AGW would respond back to REG_REQUEST and Service_REQ messages. It should either ACCEPT or REJCT it

Screenshots

If applicable, add screenshots to help explain your problem.

Additional context

019720 Thu Feb 16 14:44:43 2023 7FC670A90700 DEBUG MME-AP tasks/mme_app/mme_app_state_mana:0094 Inside get_state with read_from_db 0 019721 Thu Feb 16 14:45:11 2023 7FC669929700 DEBUG UTIL tasks/grpc_service/S1apServiceIm:0043 Received GetENBState GRPC request 019722 Thu Feb 16 14:45:21 2023 7FC6680A0700 DEBUG SCTP tasks/sctp/sctp_itti_messaging.c:0100 Ppid NGAP in sctp_itti_send_new_message_ind 019723 Thu Feb 16 14:45:21 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_SCTP] id:[113] name:[SCTP_DATA_IND] 019724 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 729. 019725 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0074 Entering ngap_amf_handle_initial_ue_message() 019726 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0080 Received NGAP INITIAL_UE_MESSAGE GNB_UE_NGAP_ID 27 019727 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0093 New Initial UE message received with gNB UE NGAP ID: 27 019728 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0195 NGAP_FIND_PROTOCOLIE_BY_ID: /home/radtonics/Documents/code/rt401_debug/rt-core/lte/gateway/c/core/oai/tasks/ngap/ngap_amf_nas_procedures.c 195: Optional ie is NULL 019729 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_itti_messagi:0097 Entering ngap_amf_itti_ngap_initial_ue_message() 019730 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_itti_messagi:0127 Leaving ngap_amf_itti_ngap_initial_ue_message() 019731 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0237 Leaving ngap_amf_handle_initial_ue_message() (rc=0) 019732 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_main.cpp :0063 Received msg from :[TASK_NGAP] id:[88] name:[NGAP_INITIAL_UE_MESSAGE] 019733 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0326 INITIAL UE Message: Valid amf_set_id and S-TMSI received 019734 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019735 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0233 Construct GUTI using S-TMSI received form UE and AMG set Id and pointerPLMN id from AMF Conf: 228d6900, 4 0 019736 Thu Feb 16 14:45:21 2023 7FC670279700 ERROR AMF-AP tasks/amf/amf_app_handler.cpp :0355 AMF_APP_INITAIL_UE_MESSAGE: gnb_ngap_id_key 70373039144985 has valid value 019737 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_msg.cpp :0049 [240650000100002] Sending UE Context Release Cmd to NGAP for (ue_id = 25) UE Context Release Cause = (1) 019738 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_client_servicer.cp:0031 Sending msg to :[TASK_NGAP] id: [85]-[NGAP_UE_CONTEXT_RELEASE_COMMAND] 019739 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0446 UE context request received: 1

019740 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_client_servicer.cp:0031 Sending msg to :[TASK_NGAP] id: [136]-[AMF_APP_NGAP_AMF_UE_ID_NOTIFICATION] 019741 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0461 Sending NAS Establishment Indication to NAS for ue_id = (26) 019742 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0421 epd:7e, security_header_type:1, message_authentication_code:165a2890, sequence_number:19 019743 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0984 M5G_NAS_SECURITY_ALGORITHMS_5G_IA2 dir UPLINK count.seq_num 25 count 25 019744 Thu Feb 16 14:45:21 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0065 Byte length: 99, Zero bits: 0: 019746 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0156 Finished writing state 019745 Thu Feb 16 14:45:21 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0067 m: (99 bytes) 00 00 00 19 08 00 00 00 19 7e 00 41 12 00 0b f2 42 f0 56 50 01 01 22 8d 69 00 2e 04 f0 70 f0 70 71 00 40 7e 00 41 12 00 0b f2 42 f0 56 50 01 01 22 8d 69 00 10 01 03 2e 04 f0 70 f0 70 2f 02 01 01 52 42 f0 56 00 00 01 17 07 f0 70 c0 40 19 80 b0 40 02 02 00 50 02 02 00 18 01 01 74 00 00 90 53 01 01 019747 Thu Feb 16 14:45:21 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0068 Key: (16 bytes) b9 f9 59 f9 37 f2 b1 e9 ea c3 ed e7 51 c0 3c 0a 019748 Thu Feb 16 14:45:21 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_AMF_APP] id:[85] name:[NGAP_UE_CONTEXT_RELEASE_COMMAND] 019750 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 1604. 019749 Thu Feb 16 14:45:21 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0070 Message: (91 bytes) 19 7e 00 41 12 00 0b f2 42 f0 56 50 01 01 22 8d 69 00 2e 04 f0 70 f0 70 71 00 40 7e 00 41 12 00 0b f2 42 f0 56 50 01 01 22 8d 69 00 10 01 03 2e 04 f0 70 f0 70 2f 02 01 01 52 42 f0 56 00 00 01 17 07 f0 70 c0 40 19 80 b0 40 02 02 00 50 02 02 00 18 01 01 74 00 00 90 53 01 01 019751 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1173 Entering ngap_handle_ue_context_release_command() 019752 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1079 Entering ngap_amf_generate_ue_context_release_command() 019753 Thu Feb 16 14:45:21 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0079 Out: (16 bytes) 16 5a 28 90 48 29 e1 26 e0 2e c1 ae e9 78 9c ed 019754 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0057 Entering ngap_amf_encode_pdu() 019755 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :1005 M5G_NAS_SECURITY_ALGORITHMS_5G_IA2 returned MAC 16.5a.28.90(2418563606) for length 91direction 0, count 25 019756 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0088 Entering ngap_amf_encode_initiating() 019757 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0730 No decryption of message length 90according to security header type 0x01 019758 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0113 Leaving ngap_amf_encode_initiating() (rc=0) 019759 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0092 Decoding AMF Message Header 019760 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0078 Leaving ngap_amf_encode_pdu() (rc=0) 019761 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0097 EPD = 0x7E, SecurityHeader = 0x0, MessageType = 0x41 019763 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0048 Header Decoded successfully 019762 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1625 Entering ngap_amf_release_ue_context() 019764 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_handlers.c :1627 [240650000100002] Releasing UE Context for UE id25 019766 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_handlers.c :1644 [240650000100002] Removed NGAP UE 25 019765 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0049 EPD = 0x7E, SecurityHeader = 0x0, MessageType = 0x41 019767 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0153 Decoding AMF message : REG_REQUEST 019769 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0235 Removing UE state for IMSI 000000000000000 019768 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0189 [REG_REQUEST] Msg plain decode bytes[0-94] 7e 01 16 5a 28 90 19 7e 00 41 12 00 0b f2 42 f0
56 50 01 01 22 8d 69 00 2e 04 f0 70 f0 70 71 00
40 7e 00 41 12 00 0b f2 42 f0 56 50 01 01 22 8d
69 00 10 01 03 2e 04 f0 70 f0 70 2f 02 01 01 52
42 f0 56 00 00 01 17 07 f0 70 c0 40 19 80 b0 40
02 02 00 50 02 02 00 18 01 01 74 00 00 90 53 01
01

019771 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/nas5g_message.cpp :0195 Decoded msg(nas5g) id: [41]-name [REG_REQUEST]

019774 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_recv.cpp :0289 Received registration type MOBILITY UPDATING REGISTRATION TYPE 019775 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1648 Leaving ngap_amf_release_ue_context() 019776 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1161 Leaving ngap_amf_generate_ue_context_release_command() (rc=0) 019777 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1200 Leaving ngap_handle_ue_context_release_command() (rc=0) 019778 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019779 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_state_converte:0163 IMSI table to proto 019780 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0156 Finished writing state 019781 Thu Feb 16 14:45:21 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_AMF_APP] id:[136] name:[AMF_APP_NGAP_AMF_UE_ID_NOTIFICATION] 019782 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP include/state_manager.hpp :0156 Finished writing state 019783 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 4567. 019784 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0896 Entering ngap_handle_amf_ue_id_notification() 019785 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_main.cpp :0063 Received msg from :[TASK_NGAP] id:[86] name:[NGAP_UE_CONTEXT_RELEASE_COMPLETE] 019786 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0918 Associated sctp_assoc_id 5, gnb_ue_ngap_id 27, amf_ue_ngap_id 26:HASH_TABLE_OK 019788 Thu Feb 16 14:45:21 2023 7FC66B986700 TRACE AMF-AP tasks/ngap/ngap_amf_nas_procedur:0924 Leaving ngap_handle_amf_ue_id_notification() 019787 Thu Feb 16 14:45:21 2023 7FC670279700 WARNI AMF-AP tasks/amf/amf_app_ue_context.cpp:0363 amf_ue_ngap_id 25does not exist 019789 Thu Feb 16 14:45:21 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_handler.cpp :1404 Received UE context release complete message for ue_id: 25 019791 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019790 Thu Feb 16 14:45:21 2023 7FC670279700 ERROR AMF-AP tasks/amf/amf_app_handler.cpp :1410 UE context doesn't exist for ue_id 25 019792 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_state_converte:0316 State PLMN 240.65 to proto 019793 Thu Feb 16 14:45:21 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0156 Finished writing state 019794 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP include/state_manager.hpp :0208 Finished writing UE state for IMSI 240650000100002 019795 Thu Feb 16 14:45:21 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_state_converte:0163 IMSI table to proto 019796 Thu Feb 16 14:45:22 2023 7FC667868700 DEBUG SCTP tasks/sctp/sctp_itti_messaging.c:0100 Ppid NGAP in sctp_itti_send_new_message_ind 019797 Thu Feb 16 14:45:22 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_SCTP] id:[113] name:[SCTP_DATA_IND] 019798 Thu Feb 16 14:45:22 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 994. 019799 Thu Feb 16 14:45:22 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1213 Entering ngap_amf_handle_ue_context_release_complete() 019800 Thu Feb 16 14:45:22 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_handlers.c :1233 UE Context Release commplete: Ng context cleared. Ignore message for ueid 25 019801 Thu Feb 16 14:45:22 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1238 Leaving ngap_amf_handle_ue_context_release_complete() (rc=0) 019802 Thu Feb 16 14:45:22 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019803 Thu Feb 16 14:45:29 2023 7FC6680A0700 DEBUG SCTP tasks/sctp/sctp_itti_messaging.c:0100 Ppid NGAP in sctp_itti_send_new_message_ind 019804 Thu Feb 16 14:45:29 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_SCTP] id:[113] name:[SCTP_DATA_IND] 019805 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 654. 019806 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0074 Entering ngap_amf_handle_initial_ue_message() 019807 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0080 Received NGAP INITIAL_UE_MESSAGE GNB_UE_NGAP_ID 28 019808 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0093 New Initial UE message received with gNB UE NGAP ID: 28 019809 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0195 NGAP_FIND_PROTOCOLIE_BY_ID: /home/radtonics/Documents/code/rt401_debug/rt-core/lte/gateway/c/core/oai/tasks/ngap/ngap_amf_nas_procedures.c 195: Optional ie is NULL 019810 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_itti_messagi:0097 Entering ngap_amf_itti_ngap_initial_ue_message() 019811 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_itti_messagi:0127 Leaving ngap_amf_itti_ngap_initial_ue_message() 019812 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0237 Leaving ngap_amf_handle_initial_ue_message() (rc=0) 019813 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_main.cpp :0063 Received msg from :[TASK_NGAP] id:[88] name:[NGAP_INITIAL_UE_MESSAGE] 019814 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0326 INITIAL UE Message: Valid amf_set_id and S-TMSI received 019815 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019816 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0233 Construct GUTI using S-TMSI received form UE and AMG set Id and pointerPLMN id from AMF Conf: 228d6900, 4 0 019817 Thu Feb 16 14:45:29 2023 7FC670279700 ERROR AMF-AP tasks/amf/amf_app_handler.cpp :0355 AMF_APP_INITAIL_UE_MESSAGE: gnb_ngap_id_key 70373039144987 has valid value 019818 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_msg.cpp :0049 [240650000100002] Sending UE Context Release Cmd to NGAP for (ue_id = 26) UE Context Release Cause = (1) 019819 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_client_servicer.cp:0031 Sending msg to :[TASK_NGAP] id: [85]-[NGAP_UE_CONTEXT_RELEASE_COMMAND] 019820 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0446 UE context request received: 1

019821 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_client_servicer.cp:0031 Sending msg to :[TASK_NGAP] id: [136]-[AMF_APP_NGAP_AMF_UE_ID_NOTIFICATION] 019822 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :0461 Sending NAS Establishment Indication to NAS for ue_id = (27) 019823 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0421 epd:7e, security_header_type:1, message_authentication_code:cfdab90, sequence_number:1a 019824 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0984 M5G_NAS_SECURITY_ALGORITHMS_5G_IA2 dir UPLINK count.seq_num 26 count 26 019825 Thu Feb 16 14:45:29 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0065 Byte length: 46, Zero bits: 0: 019826 Thu Feb 16 14:45:29 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0067 m: (46 bytes) 00 00 00 1a 08 00 00 00 1a 7e 00 4c 11 00 07 f4 01 01 22 8d 69 00 71 00 15 7e 00 4c 11 00 07 f4 01 01 22 8d 69 00 40 02 02 00 50 02 02 00 019827 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0156 Finished writing state 019828 Thu Feb 16 14:45:29 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0068 Key: (16 bytes) b9 f9 59 f9 37 f2 b1 e9 ea c3 ed e7 51 c0 3c 0a 019829 Thu Feb 16 14:45:29 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0070 Message: (38 bytes) 1a 7e 00 4c 11 00 07 f4 01 01 22 8d 69 00 71 00 15 7e 00 4c 11 00 07 f4 01 01 22 8d 69 00 40 02 02 00 50 02 02 00 019830 Thu Feb 16 14:45:29 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_AMF_APP] id:[85] name:[NGAP_UE_CONTEXT_RELEASE_COMMAND] 019832 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 755. 019831 Thu Feb 16 14:45:29 2023 7FC670279700 TRACE NAS lib/secu/nas_stream_eia2.c :0079 Out: (16 bytes) 0c fd ab 90 be 12 a0 0a d1 6f 8e f5 33 bd 11 d2 019833 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1173 Entering ngap_handle_ue_context_release_command() 019834 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :1005 M5G_NAS_SECURITY_ALGORITHMS_5G_IA2 returned MAC c.fd.ab.90(2427190540) for length 38direction 0, count 26 019835 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1079 Entering ngap_amf_generate_ue_context_release_command() 019836 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0730 No decryption of message length 37according to security header type 0x01 019837 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0057 Entering ngap_amf_encode_pdu() 019838 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0092 Decoding AMF Message Header 019839 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0088 Entering ngap_amf_encode_initiating() 019840 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0097 EPD = 0x7E, SecurityHeader = 0x0, MessageType = 0x4C 019841 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0048 Header Decoded successfully 019843 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0049 EPD = 0x7E, SecurityHeader = 0x0, MessageType = 0x4C 019842 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0113 Leaving ngap_amf_encode_initiating() (rc=0) 019844 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS5G tasks/nas5g/src/AmfMessage.cpp :0153 Decoding AMF message : M5G_SERVICE_REQUEST 019845 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_encoder.c :0078 Leaving ngap_amf_encode_pdu() (rc=0) 019846 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/nas5g_message.cpp :0189 [M5G_SERVICE_REQUEST] Msg plain decode bytes[0-40] 7e 01 0c fd ab 90 1a 7e 00 4c 11 00 07 f4 01 01
22 8d 69 00 71 00 15 7e 00 4c 11 00 07 f4 01 01
22 8d 69 00 40 02 02 00 50 02 02 00 019847 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1625 Entering ngap_amf_release_ue_context() 019848 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/nas5g_message.cpp :0195 Decoded msg(nas5g) id: [4c]-name [M5G_SERVICE_REQUEST] 019849 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_handlers.c :1627 [240650000100002] Releasing UE Context for UE id26 019850 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_recv.cpp :0056 Received TMSI in message : 228d6900 019851 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_handlers.c :1644 [240650000100002] Removed NGAP UE 26 019852 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS-AM tasks/amf/amf_recv.cpp :0074 TMSI stored in AMF CONTEXT 228d6900 019853 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS-AM tasks/amf/amf_recv.cpp :0076 TMSI received 228d6900 019854 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0235 Removing UE state for IMSI 000000000000000 019855 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS-AM tasks/amf/amf_recv.cpp :0079 TMSI matched for UE ID 27 receved TMSI 228D6900 stored TMSI 228D6900

019859 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1648 Leaving ngap_amf_release_ue_context() 019861 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1161 Leaving ngap_amf_generate_ue_context_release_command() (rc=0) 019860 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS-AM tasks/amf/amf_recv.cpp :0113 Service request type is Data 019862 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1200 Leaving ngap_handle_ue_context_release_command() (rc=0) 019863 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG NAS-AM tasks/amf/amf_recv.cpp :0167 Sending session request to SMF on service request forimsi 240650000100002 sessionid 1 019864 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019865 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_smf_send.cpp :0871 Notification gRPC filled with IMSI 240650000100002 and ue_state_idle is set to true 019866 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0156 Finished writing state 019867 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_state_converte:0163 IMSI table to proto 019868 Thu Feb 16 14:45:29 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_AMF_APP] id:[136] name:[AMF_APP_NGAP_AMF_UE_ID_NOTIFICATION] 019869 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 3105. 019870 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0896 Entering ngap_handle_amf_ue_id_notification() 019871 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP include/state_manager.hpp :0156 Finished writing state 019872 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0918 Associated sctp_assoc_id 5, gnb_ue_ngap_id 28, amf_ue_ngap_id 27:HASH_TABLE_OK 019873 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE AMF-AP tasks/ngap/ngap_amf_nas_procedur:0924 Leaving ngap_handle_amf_ue_id_notification() 019874 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_main.cpp :0063 Received msg from :[TASK_NGAP] id:[86] name:[NGAP_UE_CONTEXT_RELEASE_COMPLETE] 019875 Thu Feb 16 14:45:29 2023 7FC670279700 WARNI AMF-AP tasks/amf/amf_app_ue_context.cpp:0363 amf_ue_ngap_id 26does not exist 019876 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019877 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_handler.cpp :1404 Received UE context release complete message for ue_id: 26 019878 Thu Feb 16 14:45:29 2023 7FC670279700 ERROR AMF-AP tasks/amf/amf_app_handler.cpp :1410 UE context doesn't exist for ue_id 26 019879 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_state_converte:0316 State PLMN 240.65 to proto 019880 Thu Feb 16 14:45:29 2023 7FC667868700 DEBUG SCTP tasks/sctp/sctp_itti_messaging.c:0100 Ppid NGAP in sctp_itti_send_new_message_ind 019882 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP include/state_manager.hpp :0208 Finished writing UE state for IMSI 240650000100002 019881 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP include/state_manager.hpp :0156 Finished writing state 019883 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_state_converte:0163 IMSI table to proto 019884 Thu Feb 16 14:45:29 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_SCTP] id:[113] name:[SCTP_DATA_IND] 019885 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 1013. 019886 Thu Feb 16 14:45:29 2023 7FC6602FA700 INFO UTIL tasks/grpc_service/AmfServiceImp:0066 Received GRPC SetSmNotificationContext request 019887 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP include/state_manager.hpp :0156 Finished writing state 019888 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1213 Entering ngap_amf_handle_ue_context_release_complete() 019889 Thu Feb 16 14:45:29 2023 7FC6602FA700 INFO UTIL tasks/grpc_service/amf_service_h:0042 Sending itti_n11_create_pdu_session_response to AMF 019890 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_handlers.c :1233 UE Context Release commplete: Ng context cleared. Ignore message for ueid 0 019891 Thu Feb 16 14:45:29 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_handlers.c :1238 Leaving ngap_amf_handle_ue_context_release_complete() (rc=0) 019892 Thu Feb 16 14:45:29 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_state_converter.:0226 Writing Ngap_Supported TAI list at index 0 019893 Thu Feb 16 14:45:29 2023 7FC670279700 INFO AMF-AP tasks/amf/amf_app_main.cpp :0063 Received msg from :[TASK_GRPC_SERVICE] id:[177] name:[N11_NOTIFICATION_RECEIVED] 019894 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :1569 IMSI is 240650000100002 240650000100002 019895 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :1629 Service Accept notification received 019896 Thu Feb 16 14:45:29 2023 7FC670279700 DEBUG AMF-AP tasks/amf/amf_app_handler.cpp :1632 default case nothing to do 019897 Thu Feb 16 14:45:40 2023 7FC6680A0700 DEBUG SCTP tasks/sctp/sctp_itti_messaging.c:0100 Ppid NGAP in sctp_itti_send_new_message_ind 019898 Thu Feb 16 14:45:40 2023 7FC66B986700 INFO NGAP tasks/ngap/ngap_amf.c :0084 Received msg from :[TASK_SCTP] id:[113] name:[SCTP_DATA_IND] 019899 Thu Feb 16 14:45:40 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf.c :0094 NGAP ZMQ latency: 543. 019900 Thu Feb 16 14:45:40 2023 7FC66B986700 TRACE NGAP tasks/ngap/ngap_amf_nas_procedur:0074 Entering ngap_amf_handle_initial_ue_message() 019901 Thu Feb 16 14:45:40 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0080 Received NGAP INITIAL_UE_MESSAGE GNB_UE_NGAP_ID 29 019902 Thu Feb 16 14:45:40 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0093 New Initial UE message received with gNB UE NGAP ID: 29 019903 Thu Feb 16 14:45:40 2023 7FC66B986700 DEBUG NGAP tasks/ngap/ngap_amf_nas_procedur:0195 NGAP_FIND_PROTOCOLIE_BY_ID: /home/radtonics/Documents/code/rt401_debug/rt-core/lte/gateway/c/core/oai/tasks/ngap/ngap_amf_nas_procedures.c 195: Optional ie is NULL

shashidhar-patil commented 1 year ago

Hi @Sujay-Radtonics, can you provide pcap for this scenario? it'll help us in debugging the scenario.

We tested REG_REQ of type MOBILITY UPDATING REGISTRATION TYPE, the registration is successful. Reg_req_15029

Sujay-Radtonics commented 1 year ago

Hello @shashidhar-patil, It is very difficult for me to get a capture as there is no specific time when issue happens. It happens when UE is in active state doing traffic. However, I found a case while doing some other tests (capture) where I see Mobility updating type reg request and no response from AGW. In this case, UE was in IDLE state, so it recovered when next service request came.
In case of UE being active, both Mobility Update type and Service Request are not responded by AGW (earlier logs attached in this mail). In pcap below, please check for packet 75 and 418. There is no response to that from AGW. In code, I see that Mobility update reg request is handled only if it is a new ue context request, which could the case which you are seeing. In my case, since UE/session is active, it is not a new context.

reg_req_pcap.zip

Sujay-Radtonics commented 1 year ago

In https://github.com/magma/magma/blob/master/lte/gateway/c/core/oai/tasks/amf/amf_recv.cpp, function - amf_handle_registration_request, there is condition to handle different registration types

If you see this code snipped below, there is code to handle MOBILITY UPDATING type if amf_ctx_new is set to true. But if amf_ctx_new is false and reg type is MOBILITY UPDATING, it goes return error. So, no response is sent to this.

How should this condition be handled ?

// If registration type is initial registration or // Context is new and registration type is mobile updating start registration Line 293 - if ((params->m5gsregistrationtype == AMF_REGISTRATION_TYPE_INITIAL) || ((is_amf_ctx_new == true) && (params->m5gsregistrationtype == AMF_REGISTRATION_TYPE_MOBILITY_UPDATING))) {

} else if (params->m5gsregistrationtype == AMF_REGISTRATION_TYPE_PERIODIC_UPDATING) {

} else { OAILOG_FUNC_RETURN(LOG_NAS_AMF, RETURNerror); }

shashidhar-patil commented 1 year ago

Hello @Sujay-Radtonics, Thank you for the detailed description and PCAP. We are looking into this.

Sujay-Radtonics commented 1 year ago

Hello @shashidhar-patil, I am seeing this issue more often now. Really affecting stability of the system. Cannot run UEs for more than couple of hours. Any clue on what is happening ?

shashidhar-patil commented 1 year ago

Hi @Sujay-Radtonics, We have identified the fix, it is in the review cycle.

Sujay-Radtonics commented 1 year ago

Hi @shashidhar-patil , I see that for every Mobility updating registration, we always send Initial Context Request (Unlike Periodic registration). Is this necessary ? I hit an issue where in UE is in Active state and when we get Mobility Updating Reg, there is a context response with PDU information. This resulted in error called duplicate session and removing the existing session. After this, session request came in, but it was ignored as no session exists. UE is stuck