root@u16c131:~# /root/openairinterface5g/cmake_targets/tools/run_enb_ue_virt_s1 sudo: unable to resolve host u16c131 OPENAIR_DIR = /root/openairinterface5g Bringup UE interface... RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory RTNETLINK answers: No such file or directory working directory: /root/openairinterface5g/targets/bin eNB configuration file is /root/openairinterface5g/targets/PROJECTS/GENERIC-LTE-EPC/CONF/enb.band7.generic.oaisim.local_mme.conf num component carrier 1 ---------------------------------------------------------------------- ENB CONFIG FILE CONTENT LOADED (TBC): ---------------------------------------------------------------------- ENB CONFIG for instance 0: eNB name: eNB_Eurecom_LTEBox: eNB ID: 3584: Cell type: CELL_MACRO_ENB: TAC: 1: MCC: 1: MNC: 01: node_function for CC 0: eNodeB_3GPP: node_timing for CC 0: synch_to_ext_device: node_synch_ref for CC 0: 0: eutra band for CC 0: 7: downlink freq for CC 0: 2680000000: uplink freq offset for CC 0: -120000000: Cell ID for CC 0: 0: N_RB_DL for CC 0: 25: nb_antenna_ports for CC 0: 2: nb_antennas_tx for CC 0: 2: nb_antennas_rx for CC 0: 2: rach_numberOfRA_Preambles for CC 0: 15: rach_preamblesGroupAConfig for CC 0: 0: rach_powerRampingStep for CC 0: 1: rach_preambleInitialReceivedTargetPower for CC 0: 10: rach_preambleTransMax for CC 0: 6: rach_raResponseWindowSize for CC 0: 7: rach_macContentionResolutionTimer for CC 0: 5: rach_maxHARQ_Msg3Tx for CC 0: 4: bcch_modificationPeriodCoeff for CC 0: 0: pcch_defaultPagingCycle for CC 0: 2: pcch_nB for CC 0: 2: prach_root for CC 0: 0: prach_config_index for CC 0: 0: prach_high_speed for CC 0: 0: prach_zero_correlation for CC 0: 1: prach_freq_offset for CC 0: 2: pdsch_referenceSignalPower for CC 0: 0: pdsch_p_b for CC 0: 0: pusch_n_SB for CC 0: 1: pusch_hoppingMode for CC 0: 0: pusch_hoppingOffset for CC 0: 0: pusch_enable64QAM for CC 0: 0: pusch_groupHoppingEnabled for CC 0: 1: pusch_groupAssignment for CC 0: 0: pusch_sequenceHoppingEnabled for CC 0: 0: pusch_nDMRS1 for CC 0: 0: pucch_delta_shift for CC 0: 0: pucch_nRB_CQI for CC 0: 1: pucch_nCS_AN for CC 0: 0: srs_enable for CC 0: 0: pusch_p0_Nominal for CC 0: -108: pucch_p0_Nominal for CC 0: -108: pusch_alpha for CC 0: 7: pucch_deltaF_Format1 for CC 0: 2: pucch_deltaF_Format1b for CC 0: 1: pucch_deltaF_Format2 for CC 0: 1: pucch_deltaF_Format2a for CC 0: 1: pucch_deltaF_Format2b for CC 0: 1: msg3_delta_Preamble for CC 0: 6: ul_CyclicPrefixLength for CC 0: 0: ue_TimersAndConstants_t300 for CC 0: 5: ue_TimersAndConstants_t301 for CC 0: 5: ue_TimersAndConstants_t310 for CC 0: 5: ue_TimersAndConstants_n310 for CC 0: 7: ue_TimersAndConstants_t311 for CC 0: 3: ue_TimersAndConstants_n311 for CC 0: 0: ue_TransmissionMode for CC 0: 1: Global log level: trace HW log level: info PHY log level: trace MAC log level: trace RLC log level: trace PDCP log level: trace RRC log level: trace UDP log level: debug GTP log level: debug OSA log level: debug -------------------------------------------------------- log init done [ITTI][D] Memory pools statistics: Pool: size, number, minimum, free, address space and memory used in Kbytes 0: 52, 11000, 11000, 11000, [0x7feff6aac010-0x7feff6b629f0] 730 1: 100, 21000, 21000, 21000, [0x7fefea8b2010-0x7fefeab04bb0] 2378 2: 1000, 10000, 10000, 10000, [0x7fefe9f01010-0x7fefea8b1790] 9921 3: 20052, 400, 400, 400, [0x7fefe9759010-0x7fefe9f00c50] 7839 4: 30052, 100, 100, 100, [0x7fefe947a010-0x7fefe9758160] 2936 Pools memory 23806 Kbytes [EMU][I]OCG log level 7, oai log level6 [EMU][N]global log level is set to (info,6) with vebosity (medium, 0x15) and frequency 1 [MAC][I]num groups is set to 1 [EMU][I][INIT] Starting NAS netlink interface [NETLINK]Opened socket with fd 39 [EMU][I]Total number of UE 2 (first local 0 , num local 2, remote 0, relay 0) mobility STATIC [EMU][I]Total number of eNB 1 (local 1, remote 0, relay 0) mobility STATIC [PHY][I]init lte parms: Nid_cell 0, Frame type 0, N_RB_DL 25 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I][eNB 0] Initializing DL_FRAME_PARMS : N_RB_DL 25, PHICH Resource 1, PHICH Duration 0 [openair][LTE_PHY][INIT] common_vars->txdataF[0][0] = 0x7fefe8cb0040 (286720 bytes) [openair][LTE_PHY][INIT] common_vars->txdataF[0][1] = 0x7fefe8c69040 (286720 bytes) [openair][LTE_PHY][INIT] common_vars->txdataF[0][5] = 0x7fefe8c22040 (286720 bytes) [openair][LTE_PHY][INIT] common_vars->txdata[0][0] = 0x7fefe8bd6040 (307200 bytes) [openair][LTE_PHY][INIT] common_vars->txdata[0][1] = 0x7fefe8b8a040 (307200 bytes) [openair][LTE_PHY][INIT] common_vars->rxdata[0][0] = 0x7fefe8b3e040 (307200 bytes) [openair][LTE_PHY][INIT] common_vars->rxdata_7_5kHz[0][0] = 0x180af540 (61440 bytes) [openair][LTE_PHY][INIT] common_vars->rxdata[0][1] = 0x7fefe8af2040 (307200 bytes) [openair][LTE_PHY][INIT] common_vars->rxdata_7_5kHz[0][1] = 0x180e2660 (61440 bytes) [openair][LTE_PHY][INIT] prach_vars->rxsigF[0] = 0x184d66a0 [openair][LTE_PHY][INIT] prach_vars->rxsigF[1] = 0x184dc700 [openair][LTE_PHY][INIT] prach_vars->prach_ifft[0] = 0x184e2760 [openair][LTE_PHY][INIT] prach_vars->prach_ifft[1] = 0x184e37c0 [PHY][I]init eNB: Node Function 0 [PHY][I]init eNB: Nid_cell 0 [PHY][I]init eNB: frame_type 0,tdd_config 3 [PHY][I]init eNB: number of ue max 20 number of enb max 7 number of harq pid max 8 [PHY][I]init eNB: N_RB_DL 25 [PHY][I]init eNB: prach_config_index 0 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 0 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 0 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 1 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 1 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 2 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 2 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 3 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 3 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 4 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 4 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 5 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 5 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 6 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 6 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 7 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 7 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 8 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 8 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 9 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 9 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 10 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 10 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 11 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 11 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 12 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 12 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 13 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 13 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 14 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 14 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 15 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 15 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 16 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 16 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 17 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 17 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 18 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 18 [PHY][I]Allocating Transport Channel Buffers for DLSCH, UE 19 [PHY][I]Allocating Transport Channel Buffer for ULSCH, UE 19 Initializing UE vars (abstraction 0) for eNB TXant 1, UE RXant 1 Initializing UE vars (abstraction 0) for eNB TXant 1, UE RXant 1 AFTER init: MAX_NUM_CCs 1, Nid_cell 0 frame_type 0,tdd_config 3 [PHY][I]Initializing eNB 0 CC_id 0 : (eNodeB_3GPP,synch_to_ext_device) setup_eNB_buffers: frame_parms = 0x7fefe8cf7788 [PHY][I]Initializing eNB 0 CC_id 0 (eNodeB_3GPP,synch_to_ext_device), Creating te_thread [HW][I][SCHED][eNB] eNB_thread_single started on CPU 2 TID 54489, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 CPU_2 CPU_3 [PHY][I]thread te created id=54492[HW][I][SCHED][eNB] eNB_thread_prach started on CPU 3 TID 54493, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 CPU_2 CPU_3 [HW][I][SCHED][eNB] eNB_thread_synch started on CPU 3 TID 54494, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 CPU_2 CPU_3 [EMU][I]UE 0 mode is initialized to 0 [EMU][I]UE 1 mode is initialized to 0 UE threads created by 54031 [MAC][I][MAIN] MAC_INIT_GLOBAL_PARAM IN... [MAC][I][MAIN] CALLING RLC_MODULE_INIT... CPU Affinity of thread UHD Threads is 0 1 2 3 CPU Affinity of thread UHD Threads is 0 1 2 3 waiting for sync (eNB_thread_synch) waiting for sync (eNB_thread_single) [MAC][I][MAIN] RLC_MODULE_INIT OK, malloc16 for mac_rlc_xface... [MAC][I][MAIN] malloc16 OK, mac_rlc_xface @ 0x20242440 [MAC][I][MAIN] RLC interface setup and init [PDCP][I]PDCP layer has been initialized [MAC][I][MAIN] Init Global Param Done [MAC][I][MAIN] init eNB MAC functions [MAC][I][MAIN] init UE MAC functions [MAC][I][MAIN] PHY Frame configuration [MAC][I][MAIN] Init function start:Nb_UE_INST=2 [MAC][I][UE0] Applying default macMainConfig [MAC][I][UE1] Applying default macMainConfig [MAC][I][MAIN] Init function start:Nb_eNB_INST=1 waiting for sync (UHD Threads) Locked sync_mutex, waiting (UHD Threads) waiting for sync (UHD Threads) Locked sync_mutex, waiting (UHD Threads) [MAC][I][MAIN] calling RRC [RRC][I]Allocating 408 bytes for UE_EUTRA_Capability [PHY][I][RRC]UE Capability encoded, 15 bytes (120 bits) [RRC][I][UE] eMBMS active state is 0 [RRC][I][eNB] handover active state is 0 [RRC][I][eNB] eMBMS active state is 0 [MAC][I][MAIN][INIT] Init function finished HW: Configuring card 0, nb_antennas_tx/rx 2/2 Card 0, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 0, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 0, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 0, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 1, nb_antennas_tx/rx 2/2 Card 1, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 1, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 1, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 1, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 2, nb_antennas_tx/rx 2/2 Card 2, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 2, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 2, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 2, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 3, nb_antennas_tx/rx 2/2 Card 3, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 3, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 3, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 3, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 4, nb_antennas_tx/rx 2/2 Card 4, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 4, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 4, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 4, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 5, nb_antennas_tx/rx 2/2 Card 5, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 5, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 5, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 5, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 6, nb_antennas_tx/rx 2/2 Card 6, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 6, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 6, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 6, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 7, nb_antennas_tx/rx 2/2 Card 7, channel 0, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 7, channel 1, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 7, channel 2, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 Card 7, channel 3, Setting tx_gain 0.000000, rx_gain 130.000000, tx_freq 0.000000, rx_freq 0.000000 [OCM][I]Running with frame_type 0 (FDD), Nid_cell 0, N_RB_DL 25, EP 0, mode 2, target dl_mcs 16, rate adaptation 0, nframes 1024, abstraction 0, channel AWGN [OCM][I]Channel Model (inside of new_channel_desc_scm)=18 [OCM][I][CHANNEL] Getting new channel descriptor, nb_tx 2, nb_rx 1, nb_taps 1, channel_length 1 AWGN: ricean_factor 0.000000 [OCM][I]Channel Model (inside of new_channel_desc_scm)=18 [OCM][I][CHANNEL] Getting new channel descriptor, nb_tx 1, nb_rx 2, nb_taps 1, channel_length 1 AWGN: ricean_factor 0.000000 [OCM][I]Channel Model (inside of new_channel_desc_scm)=18 [OCM][I][CHANNEL] Getting new channel descriptor, nb_tx 2, nb_rx 1, nb_taps 1, channel_length 1 AWGN: ricean_factor 0.000000 [OCM][I]Channel Model (inside of new_channel_desc_scm)=18 [OCM][I][CHANNEL] Getting new channel descriptor, nb_tx 1, nb_rx 2, nb_taps 1, channel_length 1 AWGN: ricean_factor 0.000000 [EMU][I]eNB_l2_stats=0x7fef800015e0 [SCTP][I]Starting SCTP layer [S1AP][I]Starting S1AP layer [UDP][I]Initializing UDP task interface [UDP][I]Initializing UDP task interface: DONE [GTPV1U][I]Initializing GTPU stack 0x10a4f00 [EMU][I]TASK_L2L1 is READY [UDP][I]Initializing UDP for local address 10.20.0.131 with port 2152 [UDP][I]Inserting new descriptor for task 11, sd 48 [UDP][I]Initializing UDP for local address 10.20.0.131 with port 2152: DONE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:145 USR-API - User's UDP socket 49 is BOUND to u16c131/10000 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:168 USR-API - Notification handlers successfully registered [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:203 EMM-MAIN - USIM application data successfully read [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:248 EMM-MAIN - usim_api_k: 8b af 47 3f 2f 8f d0 94 87 cc cb d7 09 7c 68 62 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:249 EMM-MAIN - opc: e7 34 f8 73 40 07 d6 c5 ce 7a 05 08 80 9e 7e 9c [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:403 EMM-MAIN - EMM data successfully read [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:145 USR-API - User's UDP socket 50 is BOUND to u16c131/10001 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:168 USR-API - Notification handlers successfully registered [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:203 EMM-MAIN - USIM application data successfully read [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:248 EMM-MAIN - usim_api_k: 8b af 47 3f 2f 8f d0 94 87 cc cb d7 09 7c 68 62 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:249 EMM-MAIN - opc: e7 34 f8 73 40 07 d6 c5 ce 7a 05 08 80 9e 7e 9c [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/emm_main.c:403 EMM-MAIN - EMM data successfully read [EMU][I]TASK_L2L1 received DEACTIVATE_MESSAGE in state L2L1_WAITTING [EMU][I]TASK_L2L1 received DEACTIVATE_MESSAGE in state L2L1_WAITTING [ENB_APP][I][eNB 0] eNB_app_register for instance 0 [RRC][I][eNB 0] Received RRC_CONFIGURATION_REQ [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 0] Init... [S1AP][I]Registered new eNB[0] and macro eNB id 3584 [S1AP][I][eNB 0] check the mme registration state [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 0] Checking release [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 0] Rel14 RRC detected, MBMS flag 0 [RRC][I][eNB 0] Configuration SIB2/3, MBMS = 0 [MAC][I][CONFIG][eNB 0/0] Configuring MAC/PHY [MAC][I][CONFIG]SIB2/3 Contents (partial) [MAC][I][CONFIG]pusch_config_common.n_SB = 1 [MAC][I][CONFIG]pusch_config_common.hoppingMode = 0 [MAC][I][CONFIG]pusch_config_common.pusch_HoppingOffset = 0 [MAC][I][CONFIG]pusch_config_common.enable64QAM = 0 [MAC][I][CONFIG]pusch_config_common.groupHoppingEnabled = 1 [MAC][I][CONFIG]pusch_config_common.groupAssignmentPUSCH = 0 [MAC][I][CONFIG]pusch_config_common.sequenceHoppingEnabled = 0 [MAC][I][CONFIG]pusch_config_common.cyclicShift = 0 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 0] OPENAIR RRC IN.... [SCTP][I]sctp_bindx SCTP_BINDX_ADD_ADDR socket bound to : 10.20.0.131 [SCTP][I]Converted ipv4 address 10.20.0.132 to network type [SCTP][I]connectx assoc_id 1 in progress..., used 1 addresses [SCTP][I]Inserted new descriptor for sd 51 in list, nb elements 1, assoc_id 1 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32769 [SCTP][I]Client association changed: 0 [SCTP][I]---------------------- [SCTP][I]Peer addresses: [SCTP][I] - [10.20.0.132] [SCTP][I]---------------------- [SCTP][I]---------------------- [SCTP][I]SCTP Status: [SCTP][I]assoc id .....: 1 [SCTP][I]state ........: 4 [SCTP][I]instrms ......: 2 [SCTP][I]outstrms .....: 2 [SCTP][I]fragmentation : 1452 [SCTP][I]pending data .: 0 [SCTP][I]unack data ...: 0 [SCTP][I]rwnd .........: 106496 [SCTP][I]peer info : [SCTP][I] state ....: 2 [SCTP][I] cwnd .....: 4380 [SCTP][I] srtt .....: 0 [SCTP][I] rto ......: 3000 [SCTP][I] mtu ......: 1500 [SCTP][I]---------------------- [SCTP][I]Comm up notified for sd 51, assigned assoc_id 1 [S1AP][I]3584 -> 00e000 [SCTP][I]Successfully sent 59 bytes on stream 0 for assoc_id 1 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 27 received from port 36412, on stream 0, PPID 18 [S1AP][I]Decoding message S1ap_S1SetupResponseIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3535) [S1AP][I]servedGUMMEIs.list.count 1 [S1AP][I]servedPLMNs.list.count 1 [ENB_APP][I][eNB 0] Received S1AP_REGISTER_ENB_CNF: associated MME 1 [EMU][I]TASK_L2L1 received INITIALIZE_MESSAGE in state L2L1_WAITTING [MAC][I][eNB 0] Frame 0: PHY Sync failure [NAS][I][UE 0] Received INITIALIZE_MESSAGE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:284 USR-API - 10 bytes write [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:382 USR-API - Decode user data: at+cfun=1 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/at_command.c:855 USR-API - Parsing of AT+CFUN= command succeed (fun:1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:392 USR-API - 1 AT command has been successfully decoded [NAS][I] /root/openairinterface5g/openair3/NAS/UE/nas_user.c:311 USR-MAIN - Process set parameter AT command 6 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event S1_ENABLED (1) in state NULL [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:463 EMM-PROC - Delete authentication data RAND and RES [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:233 EMM-FSM - Status changed: NULL ===> DEREGISTERED [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:552 EMM-IDLE - 6 PLMNs available for network selection [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event REGISTER_REQ (5) in state DEREGISTERED [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:463 EMM-PROC - Delete authentication data RAND and RES [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:233 EMM-FSM - Status changed: DEREGISTERED ===> DEREGISTERED.PLMN-SEARCH [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event REGISTER_REQ (5) in state DEREGISTERED.PLMN-SEARCH [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:1154 EMM-IDLE - Trying to search a suitable cell of PLMN 0 in Automatic mode [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_CELL_INFO_REQ (214) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1471 EMMAS-SAP - Send AS cell information request [NAS][I][UE] Received 1 events [NAS][I][UE 1] Received INITIALIZE_MESSAGE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:284 USR-API - 10 bytes write [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:382 USR-API - Decode user data: at+cfun=1 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/at_command.c:855 USR-API - Parsing of AT+CFUN= command succeed (fun:1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:392 USR-API - 1 AT command has been successfully decoded [NAS][I] /root/openairinterface5g/openair3/NAS/UE/nas_user.c:311 USR-MAIN - Process set parameter AT command 6 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event S1_ENABLED (1) in state NULL [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:463 EMM-PROC - Delete authentication data RAND and RES [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:233 EMM-FSM - Status changed: NULL ===> DEREGISTERED [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:552 EMM-IDLE - 6 PLMNs available for network selection [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event REGISTER_REQ (5) in state DEREGISTERED [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:463 EMM-PROC - Delete authentication data RAND and RES [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:233 EMM-FSM - Status changed: DEREGISTERED ===> DEREGISTERED.PLMN-SEARCH [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event REGISTER_REQ (5) in state DEREGISTERED.PLMN-SEARCH [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:1154 EMM-IDLE - Trying to search a suitable cell of PLMN 0 in Automatic mode [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_CELL_INFO_REQ (214) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1471 EMMAS-SAP - Send AS cell information request [NAS][I][UE] Received 1 events [RRC][I][FRAME 00000][ UE][MOD 00][RNTI 0] Init... [RRC][I][FRAME 00000][ UE][MOD 00][RNTI 0] OPENAIR RRC IN.... [RRC][I][FRAME 00000][ UE][MOD 01][RNTI 0] Init... [RRC][I][FRAME 00000][ UE][MOD 01][RNTI 0] OPENAIR RRC IN.... Sending sync to all threads got sync (eNB_thread_single) got sync (eNB_thread_synch) started UHD Threads as PID: 54496 Init_UE_threads rtd 0 proc 0 nb_threads 2 i 0 started UHD Threads as PID: 54495 Init_UE_threads rtd 0 proc 0 nb_threads 2 i 0 Init_UE_threads rtd 1 proc 1 nb_threads 2 i 1 Init_UE_threads rtd 1 proc 1 nb_threads 2 i 1 CPU Affinity of thread UE_0_proc_0 is 0 1 2 3 CPU Affinity of thread UE_1_proc_0 is 0 1 2 3 CPU Affinity of thread UE_0_proc_1 is 0 1 2 3 [NAS][I][UE 0] Received INITIALIZE_MESSAGE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:284 USR-API - 10 bytes write [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:382 USR-API - Decode user data: at+cfun=1 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/at_command.c:855 USR-API - Parsing of AT+CFUN= command succeed (fun:1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:392 USR-API - 1 AT command has been successfully decoded [NAS][I] /root/openairinterface5g/openair3/NAS/UE/nas_user.c:311 USR-MAIN - Process set parameter AT command 6 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event S1_ENABLED (1) in state DEREGISTERED.PLMN-SEARCH [NAS][E] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/EmmDeregisteredPlmnSearch.c:147 EMM-FSM - Primitive is not valid (1) [NAS][W] /root/openairinterface5g/openair3/NAS/UE/nas_user.c:249 UE-MAIN - The user procedure call failed [NAS][I][UE] Received 1 events waiting for sync (UE_1_proc_0) Locked sync_mutex, waiting (UE_1_proc_0) started UE_1_proc_0 as PID: 54512 waiting for sync (UE_0_proc_0) Locked sync_mutex, waiting (UE_0_proc_0) started UE_0_proc_0 as PID: 54511 waiting for sync (UE_0_proc_1) Locked sync_mutex, waiting (UE_0_proc_1) started UE_0_proc_1 as PID: 54513 CPU Affinity of thread UE_1_proc_1 is 0 1 2 3 [NAS][I][UE 1] Received INITIALIZE_MESSAGE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:284 USR-API - 10 bytes write [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:382 USR-API - Decode user data: at+cfun=1 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/at_command.c:855 USR-API - Parsing of AT+CFUN= command succeed (fun:1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:392 USR-API - 1 AT command has been successfully decoded [NAS][I] /root/openairinterface5g/openair3/NAS/UE/nas_user.c:311 USR-MAIN - Process set parameter AT command 6 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event S1_ENABLED (1) in state DEREGISTERED.PLMN-SEARCH [NAS][E] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/EmmDeregisteredPlmnSearch.c:147 EMM-FSM - Primitive is not valid (1) [NAS][W] /root/openairinterface5g/openair3/NAS/UE/nas_user.c:249 UE-MAIN - The user procedure call failed [NAS][I][UE] Received 1 events waiting for sync (UE_1_proc_1) Locked sync_mutex, waiting (UE_1_proc_1) started UE_1_proc_1 as PID: 54514 CPU Affinity of thread sync UE 0 is 0 1 2 3 CPU Affinity of thread sync UE 1 is 0 1 2 3 waiting for sync (sync UE 0 ) Locked sync_mutex, waiting (sync UE 0 ) started sync UE 0 as PID: 54515 [PHY][I][SCHED][UE] Check absolute frequency DL 2680000000, UL 2560000000 (oai_exit 0, rx_num_channels 2) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 waiting for sync (sync UE 1 ) Locked sync_mutex, waiting (sync UE 1 ) started sync UE 1 as PID: 54516 [PHY][I][SCHED][UE] Check absolute frequency DL 2680000000, UL 2560000000 (oai_exit 0, rx_num_channels 2) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 105 (DL 2680000000, UL 2560000000) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 105 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 110 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 110 (DL 2680000000, UL 2560000000) [EMU][I]TASK_L2L1 received ACTIVATE_MESSAGE [EMU][I]TASK_L2L1 received ACTIVATE_MESSAGE [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 115 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 115 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 120 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 120 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 125 (DL 2680000000, UL 2560000000) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 125 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 130 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 130 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 1, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][E]Not yet implemented: noise power calculation when prefix length = EXTENDED [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 135 (DL 2680000000, UL 2560000000) [PHY][I][initial_sync] trying carrier off 0 Hz, rxgain 135 (DL 2680000000, UL 2560000000) [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I][UE thread Synch] Running Initial Synch (mode 0) [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I][UE1] In synch, rx_offset 0 samples [PHY][I][UE1] Sending synch status to higher layers [PHY][I][UE 1] Frame 4 RRC Measurements => rssi -92.1 dBm (dig 42.9 dB, gain 135), N0 -140 dBm, rsrp -116.9 dBm/RE, rsrq 9.0 dB [PHY][I][UE 1] Frame 4 MIB Information => FDD, NORMAL, NidCell 0, N_RB_DL 25, PHICH DURATION 0, PHICH RESOURCE 1/6, TX_ANT 2 [HW][I]Got synch: hw_slot_offset 0, carrier off 0 Hz, rxgain 140 (DL 2680000000, UL 2560000000), UE_scan_carrier 0 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I][UE0] In synch, rx_offset 0 samples [PHY][I][UE0] Sending synch status to higher layers [PHY][I][UE 0] Frame 4 RRC Measurements => rssi -92.2 dBm (dig 42.8 dB, gain 135), N0 -144 dBm, rsrp -117.0 dBm/RE, rsrq 9.0 dB [PHY][I][UE 0] Frame 4 MIB Information => FDD, NORMAL, NidCell 0, N_RB_DL 25, PHICH DURATION 0, PHICH RESOURCE 1/6, TX_ANT 2 [HW][I]Got synch: hw_slot_offset 0, carrier off 0 Hz, rxgain 140 (DL 2680000000, UL 2560000000), UE_scan_carrier 0 CPU Freq is 3.606518 [EMU][N]>>>>>>>>>>>>>>>>>>>>>>>>>>> OAIEMU initialization done <<<<<<<<<<<<<<<<<<<<<<<<<< [EMU][I]Version: Branch: master Abrev. Hash: 67df8e0 Date: Mon Oct 23 16:42:54 2017 +0200 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [PHY][I]Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [UE 1] frame 7, subframe 0: Adjusting frame counter (PBCH ant_tx=2, frame_tx=7, phase 3, rx_offset 0) => new frame 7 [UE 1] frame 7, subframe 0: Adjusting frame counter (PBCH ant_tx=2, frame_tx=7, phase 3, rx_offset 0) => new frame 7 [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 8, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 8, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [RRC][I][UE 1] : Dumping SIB 1 [RRC][I]PLMN MCC 001, MNC 01, TAC 0x0001 [RRC][I]cellReservedForOperatorUse : raw:1 decoded:notReserved [RRC][I]Found OAI Test (name from internal table) [RRC][I]cellAccessRelatedInfo.cellIdentity : raw:3584 decoded:00.00.e0.00 [RRC][I]cellAccessRelatedInfo.cellBarred : raw:1 decoded:notBarred [RRC][I]cellAccessRelatedInfo.intraFreqReselection : raw:1 decoded:notAllowed [RRC][I]cellAccessRelatedInfo.csg_Indication : 0 [RRC][I]cellAccessRelatedInfo.csg_Identity : not defined [RRC][I]cellSelectionInfo.q_RxLevMin : -65 [RRC][I]cellSelectionInfo.q_RxLevMinOffset : not defined [RRC][I]p_Max : not defined [RRC][I]freqBandIndicator : 7 [RRC][I]si_Periodicity[0] : rf8 [RRC][I]siSchedulingInfoSIBType[0] : SIB3 [RRC][I]siWindowLength : 20ms [RRC][I]systemInfoValueTag : 0 [RRC][I][FRAME unknown][RRC_UE][MOD 01][][--- MAC_CONFIG_REQ (SIB1 params eNB 0) --->][MAC_UE][MOD 01][] [MAC][I][CONFIG][UE 1] Configuring MAC/PHY from eNB 0 [RRC][I][UE 0] : Dumping SIB 1 [RRC][I]PLMN MCC 001, MNC 01, TAC 0x0001 [RRC][I]cellReservedForOperatorUse : raw:1 decoded:notReserved [RRC][I]Found OAI Test (name from internal table) [RRC][I]cellAccessRelatedInfo.cellIdentity : raw:3584 decoded:00.00.e0.00 [RRC][I]cellAccessRelatedInfo.cellBarred : raw:1 decoded:notBarred [RRC][I]cellAccessRelatedInfo.intraFreqReselection : raw:1 decoded:notAllowed [RRC][I]cellAccessRelatedInfo.csg_Indication : 0 [RRC][I]cellAccessRelatedInfo.csg_Identity : not defined [RRC][I]cellSelectionInfo.q_RxLevMin : -65 [RRC][I]cellSelectionInfo.q_RxLevMinOffset : not defined [RRC][I]p_Max : not defined [RRC][I]freqBandIndicator : 7 [RRC][I]si_Periodicity[0] : rf8 [RRC][I]siSchedulingInfoSIBType[0] : SIB3 [RRC][I]siWindowLength : 20ms [RRC][I]systemInfoValueTag : 0 [RRC][I][FRAME unknown][RRC_UE][MOD 00][][--- MAC_CONFIG_REQ (SIB1 params eNB 0) --->][MAC_UE][MOD 00][] [MAC][I][CONFIG][UE 0] Configuring MAC/PHY from eNB 0 [NAS][I][UE 1] Received NAS_CELL_SELECTION_CNF: errCode 1, cellID 3584, tac 1 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_CELL_INFO_RES (215) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:667 EMMAS-SAP - Received AS cell information response [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:694 EMM-IDLE - One cell found for PLMN 0 in Automatic mode [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:778 EMM-IDLE - UE may camp on this suitable cell for normal services [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event REGISTER_CNF (6) in state DEREGISTERED.PLMN-SEARCH [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:233 EMM-FSM - Status changed: DEREGISTERED.PLMN-SEARCH ===> DEREGISTERED.NORMAL-SERVICE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event ATTACH_INIT (8) in state DEREGISTERED.NORMAL-SERVICE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:143 EMM-PROC - Initiate EPS attach type = EPS (0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:179 EMM-PROC - Initiate EPS attach with IMSI [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:465 EMM_AS_NO_KEY_AVAILABLE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:220 EMM-PROC - eps_encryption 0x0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:221 EMM-PROC - eps_integrity 0x2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_sap.c:155 ESM-SAP - Received primitive ESM_PDN_CONNECTIVITY_REQ (12) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:184 ESM-PROC - Define new IPv4 PDN connection to APN (null) (cid=1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:696 ESM-PROC - Create new PDN connection (pid=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:161 ESM-PROC - Assign new procedure transaction identity (cid=1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_pt.c:148 ESM-FSM - Procedure transaction identity 1 assigned [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_send.c:208 ESM-SAP - Send PDN Connectivity Request message (pti=1, ebi=0) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/ESM/MSG/esm_msg.c:269 ESM-MSG - Encoded ESM message header (3) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:290 ESM-PROC - Initiate PDN connectivity (pti=1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_pt.c:383 ESM-FSM - Status of procedure transaction 1 changed: PROCEDURE TRANSACTION INACTIVE ===> PROCEDURE TRANSACTION PENDING [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:255 EMM-PROC - Timer T3410 (-1) expires in 15 seconds [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_ESTABLISH_REQ (205) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1378 EMMAS-SAP - Send AS connection establish request [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:166 EMMAS-SAP - Send Attach Request message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:216 EMMAS-SAP - Send Attach Request message with IMSI [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/IES/UeNetworkCapability.c:115 uenetworkcapability encoded EPS 3 [NAS][I][UE] Received 1 events [NAS][I][UE 0] Received NAS_CELL_SELECTION_CNF: errCode 1, cellID 3584, tac 1 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_CELL_INFO_RES (215) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:667 EMMAS-SAP - Received AS cell information response [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:694 EMM-IDLE - One cell found for PLMN 0 in Automatic mode [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/IdleMode.c:778 EMM-IDLE - UE may camp on this suitable cell for normal services [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event REGISTER_CNF (6) in state DEREGISTERED.PLMN-SEARCH [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:233 EMM-FSM - Status changed: DEREGISTERED.PLMN-SEARCH ===> DEREGISTERED.NORMAL-SERVICE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_fsm.c:293 EMM-FSM - Received event ATTACH_INIT (8) in state DEREGISTERED.NORMAL-SERVICE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:143 EMM-PROC - Initiate EPS attach type = EPS (0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:179 EMM-PROC - Initiate EPS attach with IMSI [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:465 EMM_AS_NO_KEY_AVAILABLE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:220 EMM-PROC - eps_encryption 0x0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:221 EMM-PROC - eps_integrity 0x2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_sap.c:155 ESM-SAP - Received primitive ESM_PDN_CONNECTIVITY_REQ (12) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:184 ESM-PROC - Define new IPv4 PDN connection to APN (null) (cid=1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:696 ESM-PROC - Create new PDN connection (pid=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:161 ESM-PROC - Assign new procedure transaction identity (cid=1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_pt.c:148 ESM-FSM - Procedure transaction identity 1 assigned [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_send.c:208 ESM-SAP - Send PDN Connectivity Request message (pti=1, ebi=0) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/ESM/MSG/esm_msg.c:269 ESM-MSG - Encoded ESM message header (3) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:290 ESM-PROC - Initiate PDN connectivity (pti=1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_pt.c:383 ESM-FSM - Status of procedure transaction 1 changed: PROCEDURE TRANSACTION INACTIVE ===> PROCEDURE TRANSACTION PENDING [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:255 EMM-PROC - Timer T3410 (-1) expires in 15 seconds [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_ESTABLISH_REQ (205) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1378 EMMAS-SAP - Send AS connection establish request [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:166 EMMAS-SAP - Send Attach Request message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:216 EMMAS-SAP - Send Attach Request message with IMSI [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/IES/UeNetworkCapability.c:115 uenetworkcapability encoded EPS 3 [NAS][I][UE] Received 1 events [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 9, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 9, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [RRC][I][UE 1] Frame 9 Found SIB2 from eNB 0 [RRC][I]ac_BarringInfo : not defined [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.preambleInfo.numberOfRA_Preambles : raw:15 decoded:n64 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.preambleInfo.preamblesGroupAConfig : not defined [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.powerRampingParameters.powerRampingStep : raw:1 decoded:dB2 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.powerRampingParameters.preambleInitialReceivedTargetPower : raw:10 decoded:dBm-100 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.ra_SupervisionInfo.preambleTransMax : raw:6 decoded:n10 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.ra_SupervisionInfo.ra_ResponseWindowSize : raw:7 decoded:sf10 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.ra_SupervisionInfo.mac_ContentionResolutionTimer : raw:5 decoded:sf48 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.maxHARQ_Msg3Tx : 4 [RRC][I]radioResourceConfigCommon.bcch_Config.modificationPeriodCoeff : raw:0 decoded:n2 [RRC][I]radioResourceConfigCommon.pcch_Config.defaultPagingCycle : raw:2 decoded:rf64 [RRC][I]radioResourceConfigCommon.pcch_Config.nB : raw:2 decoded:oneT [RRC][I]radioResourceConfigCommon.prach_Config.rootSequenceIndex : 0 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.prach_ConfigIndex : 0 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.highSpeedFlag : 0 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.zeroCorrelationZoneConfig : 1 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.prach_FreqOffset : 2 [RRC][I]radioResourceConfigCommon.pdsch_ConfigCommon.referenceSignalPower : 0 [RRC][I]radioResourceConfigCommon.pdsch_ConfigCommon.p_b : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.n_SB : 1 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.hoppingMode : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.pusch_HoppingOffset : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.enable64QAM : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.groupHoppingEnabled : 1 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.groupAssignmentPUSCH : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.sequenceHoppingEnabled : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.cyclicShift : 0 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.deltaPUCCH_Shift : 0 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.nRB_CQI : 1 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.nCS_AN : 0 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.n1PUCCH_AN : 0 [RRC][I]radioResourceConfigCommon.soundingRS_UL_ConfigCommon.present : raw:1 decoded:release [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.p0_NominalPUSCH : -108 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.alpha : 7 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.p0_NominalPUCCH : -108 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format1 : 2 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format1b : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format2 : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format2a : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format2b : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaPreambleMsg3 : 6 [RRC][I]radioResourceConfigCommon.ul_CyclicPrefixLength : 0 [RRC][I]ue_TimersAndConstants.t300 : 5 [RRC][I]ue_TimersAndConstants.t301 : 5 [RRC][I]ue_TimersAndConstants.t310 : 5 [RRC][I]ue_TimersAndConstants.n310 : 7 [RRC][I]ue_TimersAndConstants.t311 : 3 [RRC][I]ue_TimersAndConstants.n311 : 0 [RRC][I]freqInfo.ul_CarrierFreq : not defined [RRC][I]freqInfo.ul_Bandwidth : not defined [RRC][I]freqInfo.additionalSpectrumEmission : 1 [RRC][I]mbsfn_SubframeConfigList : not defined [RRC][I]timeAlignmentTimerCommon : 7 [RRC][I]lateNonCriticalExtension : not defined [RRC][I]ssac_BarringForMMTEL_Voice_r9 : not defined [RRC][I]ssac_BarringForMMTEL_Video_r9 : not defined [RRC][I]ac_BarringForCSFB_r10 : not defined [RRC][I][FRAME 00009][RRC_UE][MOD 01][][--- MAC_CONFIG_REQ (SIB2 params eNB 0) --->][MAC_UE][MOD 01][] [MAC][I][CONFIG][UE 1] Configuring MAC/PHY from eNB 0 [PHY][I][UE1] Applying radioResourceConfigCommon from eNB0 [RRC][I][UE 1] Received SIB1/SIB2/SIB3 Switching to RRC_SI_RECEIVED [RRC][I][UE 1] Frame 9 Found SIB3 from eNB 0 [RRC][I]Dumping SIB3 (see TS36.331 V8.21.0) [RRC][I]cellReselectionInfoCommon.q_Hyst : raw:4 decoded:4 dB [RRC][I]cellReselectionInfoCommon.speedStateReselectionPars : not defined [RRC][I]cellReselectionServingFreqInfo.s_NonIntraSearch : not defined [RRC][I]cellReselectionServingFreqInfo.threshServingLow : 31 [RRC][I]cellReselectionServingFreqInfo.cellReselectionPriority : 7 [RRC][I]intraFreqCellReselectionInfo.q_RxLevMin : -70 [RRC][I]intraFreqCellReselectionInfo.p_Max : not defined [RRC][I]intraFreqCellReselectionInfo.s_IntraSearch : 31 [RRC][I]intraFreqCellReselectionInfo.allowedMeasBandwidth : 0 [RRC][I]intraFreqCellReselectionInfo.presenceAntennaPort1 : 0 [RRC][I]intraFreqCellReselectionInfo.neighCellConfig : 0 [RRC][I]intraFreqCellReselectionInfo.t_ReselectionEUTRA : 1 [RRC][I]intraFreqCellReselectionInfo.t_ReselectionEUTRA_SF : not defined [RRC][I]SIStatus 7, SIcnt 1/1 [RRC][I][UE 1] : Frame 9, Logical Channel UL-CCCH (SRB0), Generating RRCConnectionRequest (bytes 6, eNB 0) [RRC][I][UE 0] Frame 9 Found SIB2 from eNB 0 [RRC][I]ac_BarringInfo : not defined [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.preambleInfo.numberOfRA_Preambles : raw:15 decoded:n64 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.preambleInfo.preamblesGroupAConfig : not defined [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.powerRampingParameters.powerRampingStep : raw:1 decoded:dB2 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.powerRampingParameters.preambleInitialReceivedTargetPower : raw:10 decoded:dBm-100 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.ra_SupervisionInfo.preambleTransMax : raw:6 decoded:n10 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.ra_SupervisionInfo.ra_ResponseWindowSize : raw:7 decoded:sf10 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.ra_SupervisionInfo.mac_ContentionResolutionTimer : raw:5 decoded:sf48 [RRC][I]radioResourceConfigCommon.rach_ConfigCommon.maxHARQ_Msg3Tx : 4 [RRC][I]radioResourceConfigCommon.bcch_Config.modificationPeriodCoeff : raw:0 decoded:n2 [RRC][I]radioResourceConfigCommon.pcch_Config.defaultPagingCycle : raw:2 decoded:rf64 [RRC][I]radioResourceConfigCommon.pcch_Config.nB : raw:2 decoded:oneT [RRC][I]radioResourceConfigCommon.prach_Config.rootSequenceIndex : 0 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.prach_ConfigIndex : 0 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.highSpeedFlag : 0 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.zeroCorrelationZoneConfig : 1 [RRC][I]radioResourceConfigCommon.prach_Config.prach_ConfigInfo.prach_FreqOffset : 2 [RRC][I]radioResourceConfigCommon.pdsch_ConfigCommon.referenceSignalPower : 0 [RRC][I]radioResourceConfigCommon.pdsch_ConfigCommon.p_b : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.n_SB : 1 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.hoppingMode : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.pusch_HoppingOffset : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.pusch_ConfigBasic.enable64QAM : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.groupHoppingEnabled : 1 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.groupAssignmentPUSCH : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.sequenceHoppingEnabled : 0 [RRC][I]radioResourceConfigCommon.pusch_ConfigCommon.ul_ReferenceSignalsPUSCH.cyclicShift : 0 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.deltaPUCCH_Shift : 0 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.nRB_CQI : 1 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.nCS_AN : 0 [RRC][I]radioResourceConfigCommon.pucch_ConfigCommon.n1PUCCH_AN : 0 [RRC][I]radioResourceConfigCommon.soundingRS_UL_ConfigCommon.present : raw:1 decoded:release [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.p0_NominalPUSCH : -108 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.alpha : 7 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.p0_NominalPUCCH : -108 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format1 : 2 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format1b : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format2 : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format2a : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaFList_PUCCH.deltaF_PUCCH_Format2b : 1 [RRC][I]radioResourceConfigCommon.uplinkPowerControlCommon.deltaPreambleMsg3 : 6 [RRC][I]radioResourceConfigCommon.ul_CyclicPrefixLength : 0 [RRC][I]ue_TimersAndConstants.t300 : 5 [RRC][I]ue_TimersAndConstants.t301 : 5 [RRC][I]ue_TimersAndConstants.t310 : 5 [RRC][I]ue_TimersAndConstants.n310 : 7 [RRC][I]ue_TimersAndConstants.t311 : 3 [RRC][I]ue_TimersAndConstants.n311 : 0 [RRC][I]freqInfo.ul_CarrierFreq : not defined [RRC][I]freqInfo.ul_Bandwidth : not defined [RRC][I]freqInfo.additionalSpectrumEmission : 1 [RRC][I]mbsfn_SubframeConfigList : not defined [RRC][I]timeAlignmentTimerCommon : 7 [RRC][I]lateNonCriticalExtension : not defined [RRC][I]ssac_BarringForMMTEL_Voice_r9 : not defined [RRC][I]ssac_BarringForMMTEL_Video_r9 : not defined [RRC][I]ac_BarringForCSFB_r10 : not defined [RRC][I][FRAME 00009][RRC_UE][MOD 00][][--- MAC_CONFIG_REQ (SIB2 params eNB 0) --->][MAC_UE][MOD 00][] [MAC][I][CONFIG][UE 0] Configuring MAC/PHY from eNB 0 [PHY][I][UE0] Applying radioResourceConfigCommon from eNB0 [RRC][I][UE 0] Received SIB1/SIB2/SIB3 Switching to RRC_SI_RECEIVED [RRC][I][UE 0] Frame 9 Found SIB3 from eNB 0 [RRC][I]Dumping SIB3 (see TS36.331 V8.21.0) [RRC][I]cellReselectionInfoCommon.q_Hyst : raw:4 decoded:4 dB [RRC][I]cellReselectionInfoCommon.speedStateReselectionPars : not defined [RRC][I]cellReselectionServingFreqInfo.s_NonIntraSearch : not defined [RRC][I]cellReselectionServingFreqInfo.threshServingLow : 31 [RRC][I]cellReselectionServingFreqInfo.cellReselectionPriority : 7 [RRC][I]intraFreqCellReselectionInfo.q_RxLevMin : -70 [RRC][I]intraFreqCellReselectionInfo.p_Max : not defined [RRC][I]intraFreqCellReselectionInfo.s_IntraSearch : 31 [RRC][I]intraFreqCellReselectionInfo.allowedMeasBandwidth : 0 [RRC][I]intraFreqCellReselectionInfo.presenceAntennaPort1 : 0 [RRC][I]intraFreqCellReselectionInfo.neighCellConfig : 0 [RRC][I]intraFreqCellReselectionInfo.t_ReselectionEUTRA : 1 [RRC][I]intraFreqCellReselectionInfo.t_ReselectionEUTRA_SF : not defined [RRC][I]SIStatus 7, SIcnt 1/1 [RRC][I][UE 0] : Frame 9, Logical Channel UL-CCCH (SRB0), Generating RRCConnectionRequest (bytes 6, eNB 0) [PHY][I]mode 0 [PHY][I][UE 1][RAPROC] Frame 10, Subframe 1 : Generating PRACH, preamble 11,PL 112, P0_PRACH 12, TARGET_RECEIVED_POWER -100 dBm, PRACH TDD Resource index 0, RA-RNTI 2 [PHY][I][UE 1][RAPROC] Frame 10, subframe 1: Generating PRACH (eNB 0) preamble index 11 for UL, TX power 12 dBm (PL 112 dB), l3msg [MAC][I]Received RRC_MAC_CCCH_DATA_REQ from TASK_RRC_UE: instance 2, frameP 10, eNB_index 0 [PHY][I]mode 0 [PHY][I][UE 0][RAPROC] Frame 10, Subframe 1 : Generating PRACH, preamble 12,PL 111, P0_PRACH 11, TARGET_RECEIVED_POWER -100 dBm, PRACH TDD Resource index 0, RA-RNTI 2 [PHY][I][UE 0][RAPROC] Frame 10, subframe 1: Generating PRACH (eNB 0) preamble index 12 for UL, TX power 11 dBm (PL 111 dB), l3msg [MAC][I]Received RRC_MAC_CCCH_DATA_REQ from TASK_RRC_UE: instance 1, frameP 10, eNB_index 0 [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 10, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 10, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [MAC][I][eNB 1][RAPROC] Frame 11 Received RAR (4b|00.00.35.4c.a9.d0) for preamble 11/11 [PHY][I][UE 1] AbsoluteSubFrame 11.0, received (rar) timing_advance 0 [PHY][I]No RAR found with the intended RAPID. The closest RAPID in all RARs is 11 [MAC][I][eNB 0][RAPROC] Frame 11 Received RAR (4b|00.00.35.4c.a9.d0) for preamble 11/12 [PHY][W][UE 0][RAPROC] Received RAR preamble (12) doesn't match !!! [PHY][I][UE 1][RAPROC] Frame 11, Subframe 6 Generating (RRCConnectionRequest) Msg3 (nb_rb 2, first_rb 1, round 0, rvidx 0) Msg3: 20.6.1f|51.46.9d.a4.20.26 [PHY][I][UE 1][RAPROC] AbsSubframe 11.6: Msg3 (2 PRBs) Po_PUSCH 28 dBm (-10000,301,100*PL=12300,0,200) [MAC][I]Frame 11: Contention resolution timer 0/48 [MAC][I]Frame 11: Contention resolution timer 1/48 [MAC][I]Frame 11: Contention resolution timer 2/48 [PHY][I][eNB 0][RAPROC] Frame 11 Terminating ra_proc for harq 4, UE 0 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 11, Received CCCH: 51.46.9d.a4.20.26, Terminating RA procedure for UE rnti a9d0 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 11 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti a9d0 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 11 Added user with rnti a9d0 => UE 0 [MAC][I][eNB 0] frame 12 subfarme 0, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00011][eNB][MOD 00][RNTI a9d0] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00011][eNB][MOD 00][RNTI a9d0] Accept new connection from UE random UE identity (0x242da6914000000) MME code 0 TMSI 0 cause 3 [MAC][I][CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (a9d0) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7fef680045a0 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 2 [RRC][I][FRAME 00011][eNB][MOD 00][RNTI a9d0] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00011][eNB][MOD 00][RNTI a9d0]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00011][eNB][MOD 00][RNTI a9d0][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00011][eNB][MOD 00][RNTI a9d0] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I]Frame 12: Contention resolution timer 3/48 [MAC][I][eNB 0] frame 12 subfarme 1, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7fef680045a0 for UE 0 [RLC][I][FRAME 00011][eNB][MOD 00][RNTI a9d0][SRB AM 01][CONFIGURE] max_retx_threshold 4 poll_pdu 4 poll_byte 65535 t_poll_retransmit 80 t_reordering 35 t_status_prohibit 0 [MAC][I]Frame 12: Contention resolution timer 4/48 [PHY][I]mode 0 [PHY][I][UE 0][RAPROC] Frame 12, Subframe 1 : Generating PRACH, preamble 32,PL 111, P0_PRACH 13, TARGET_RECEIVED_POWER -98 dBm, PRACH TDD Resource index 0, RA-RNTI 2 [PHY][I][UE 0][RAPROC] Frame 12, subframe 1: Generating PRACH (eNB 0) preamble index 32 for UL, TX power 13 dBm (PL 111 dB), l3msg [MAC][I][eNB 0] frame 12 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 12: Contention resolution timer 5/48 [MAC][I][eNB 0] frame 12 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 12: Contention resolution timer 6/48 [MAC][I][eNB 0] frame 12 subfarme 4, UE 0: not configured, skipping UE scheduling [PHY][I][UE 1][PUSCH 4][RAPROC] Frame 12 subframe 0 Msg3 PHICH, received ACK (-190) nseq 1, ngroup 0 [MAC][I]Frame 12: Contention resolution timer 7/48 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 12, subframeP 5: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI a9d0) [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 12 subframeP 5 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][eNB 0] frame 12 subfarme 5, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 12: Contention resolution timer 8/48 [MAC][I][eNB 0] frame 12 subfarme 6, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 12: Contention resolution timer 9/48 [MAC][I][eNB 0] frame 12 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 12: Contention resolution timer 10/48 [MAC][I][eNB 0] frame 12 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 12: Contention resolution timer 11/48 [MAC][I][eNB 0] frame 12 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][eNB 0][RAPROC] Frame 12 Received RAR (60|00.00.35.4c.1d.0d) for preamble 32/32 [PHY][I][UE 0] AbsoluteSubFrame 12.5, received (rar) timing_advance 0 [PHY][I][UE 1] Frame 12, subframe 5: Received DCI with CRNTI a9d0 => Mode PUSCH [MAC][I]Frame 12: Contention resolution timer 12/48 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 13, subframeP 0: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti a9d0 fsf 13/0, let's configure it [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 13, subframeP 0 : Msg4 acknowledged [MAC][I][eNB 0][PUSCH 6/a9d0] CC_id 0 Frame 13 subframeP 0 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 6) [MAC][I]Frame 13: Contention resolution timer 13/48 [MAC][I]Frame 13: Contention resolution timer 14/48 [PHY][I][UE 0][RAPROC] Frame 13, Subframe 1 Generating (RRCConnectionRequest) Msg3 (nb_rb 2, first_rb 1, round 0, rvidx 0) Msg3: 20.6.1f|59.84.48.9e.22.46 [PHY][I][UE 0][RAPROC] AbsSubframe 13.1: Msg3 (2 PRBs) Po_PUSCH 19 dBm (-10000,301,100*PL=11200,0,400) [MAC][I]Frame 13: Contention resolution timer 15/48 [MAC][I]Frame 13: Contention resolution timer 0/48 [MAC][I]Frame 13: Contention resolution timer 16/48 [MAC][I]Frame 13: Contention resolution timer 1/48 [MAC][I]Frame 13: Contention resolution timer 17/48 [MAC][I]Frame 13: Contention resolution timer 2/48 [PHY][I][eNB 0][RAPROC] Frame 13 Terminating ra_proc for harq 3, UE 1 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 13, Received CCCH: 59.84.48.9e.22.46, Terminating RA procedure for UE rnti 1d0d [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 13 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 1 rnti 1d0d [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 13 Added user with rnti 1d0d => UE 1 [MAC][I][eNB 0] frame 13 subfarme 5, UE 1: not configured, skipping UE scheduling [RRC][I][FRAME 00013][eNB][MOD 00][RNTI 1d0d] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00013][eNB][MOD 00][RNTI 1d0d] Accept new connection from UE random UE identity (0x24e2894498000000) MME code 0 TMSI 0 cause 3 [MAC][I][CONFIG][eNB 0/0] Configuring MAC/PHY for UE 1 (1d0d) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7fef68023ef0 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 2 [RRC][I][FRAME 00013][eNB][MOD 00][RNTI 1d0d] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00013][eNB][MOD 00][RNTI 1d0d]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00013][eNB][MOD 00][RNTI 1d0d][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00013][eNB][MOD 00][RNTI 1d0d] [SRB 1] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00013][eNB][MOD 00][RNTI 1d0d][SRB AM 01][CONFIGURE] max_retx_threshold 4 poll_pdu 4 poll_byte 65535 t_poll_retransmit 80 t_reordering 35 t_status_prohibit 0 [MAC][I]Frame 13: Contention resolution timer 18/48 [MAC][I]Frame 13: Contention resolution timer 3/48 [MAC][I][eNB 0] frame 13 subfarme 6, UE 1: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7fef68023ef0 for UE 1 [MAC][I]Frame 13: Contention resolution timer 19/48 [MAC][I]Frame 13: Contention resolution timer 4/48 [MAC][I][eNB 0] frame 13 subfarme 7, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 13: Contention resolution timer 20/48 [MAC][I]Frame 13: Contention resolution timer 5/48 [MAC][I][eNB 0] frame 13 subfarme 8, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 13: Contention resolution timer 21/48 [MAC][I]Frame 13: Contention resolution timer 6/48 [MAC][I][eNB 0] frame 13 subfarme 9, UE 1: not configured, skipping UE scheduling [PHY][I][UE 0][PUSCH 3][RAPROC] Frame 13 subframe 5 Msg3 PHICH, received ACK (-739) nseq 1, ngroup 0 [MAC][I]Frame 13: Contention resolution timer 22/48 [MAC][I]Frame 13: Contention resolution timer 7/48 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 14, subframeP 0: Generating Msg4 with RRC Piggyback (RA proc 1, RNTI 1d0d) [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 14 subframeP 0 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][eNB 0] frame 14 subfarme 0, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 14: Contention resolution timer 23/48 [MAC][I]Frame 14: Contention resolution timer 8/48 [MAC][I][eNB 0] frame 14 subfarme 1, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 14: Contention resolution timer 24/48 [MAC][I]Frame 14: Contention resolution timer 9/48 [MAC][I][eNB 0] frame 14 subfarme 2, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 14: Contention resolution timer 25/48 [MAC][I]Frame 14: Contention resolution timer 10/48 [MAC][I][eNB 0] frame 14 subfarme 3, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 14: Contention resolution timer 26/48 [MAC][I]Frame 14: Contention resolution timer 11/48 [MAC][I][eNB 0] frame 14 subfarme 4, UE 1: not configured, skipping UE scheduling [MAC][I]Frame 14: Contention resolution timer 27/48 [PHY][I][UE 0] Frame 14, subframe 0: Received DCI with CRNTI 1d0d => Mode PUSCH [MAC][I][UE 0][RAPROC] Frame 14 : received contention resolution msg: 59.84.48.9e.22.46, Terminating RA procedure [MAC][I][UE 0][RAPROC] Frame 14 : Clearing RA_active flag [MAC][I][UE 0][RAPROC] Frame 14 : Clearing contention resolution timer [PHY][I][UE 0][RAPROC] Random-access procedure succeeded. Set C-RNTI = Temporary C-RNTI [RRC][I][UE0][RAPROC] Frame 14 : Logical Channel DL-CCCH (SRB0), Received RRCConnectionSetup RNTI 1d0d [RRC][I]Save physicalConfigDedicated if present [RRC][I]Init physicalConfigDedicated UE_rrc_inst to radioResourceConfigDedicated->physicalConfigDedicated [PDCP][N][FRAME 00014][ UE][MOD 00][RNTI 1d0d][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00014][ UE][MOD 00][RNTI 1d0d] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 14, subframeP 5: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 1d0d fsf 14/5, let's configure it [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 14, subframeP 5 : Msg4 acknowledged [MAC][I][eNB 0][PUSCH 5/1d0d] CC_id 0 Frame 14 subframeP 5 Scheduled UE 1 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 5) [RLC][I][FRAME 00014][ UE][MOD 00][RNTI 1d0d][SRB AM 01][CONFIGURE] max_retx_threshold 4 poll_pdu 4 poll_byte 65535 t_poll_retransmit 80 t_reordering 35 t_status_prohibit 0 [RRC][I][UE 0], CONFIG_SRB1 1 corresponding to eNB_index 0 [RRC][I][FRAME 00014][RRC_UE][MOD 00][][--- MAC_CONFIG_REQ (SRB1 eNB 0) --->][MAC_UE][MOD 00][] [MAC][I][CONFIG][UE 0] Configuring MAC/PHY from eNB 0 [MAC][I][CONFIG][UE 0] Applying RRC logicalChannelConfig from eNB0 [PHY][I]Transmission Mode 2 [PHY][I]C-RNTI 1d0d 1d0d [RRC][I][UE 0] State = RRC_CONNECTED (eNB 0) [RRC][I][UE 0][RAPROC] Frame 14 : Logical Channel UL-DCCH (SRB1), Generating RRCConnectionSetupComplete (bytes53, eNB 0) [PDCP][I][FRAME 00014][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 1, muiP 0, confirmP 0, mode 1 [RLC][I][FRAME 00014][ UE][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 58 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 0 vtA 0 vtS 0 [MAC][I]Frame 14: Contention resolution timer 28/48 [MAC][I]Frame 14: Contention resolution timer 29/48 [MAC][I]Frame 14: Contention resolution timer 30/48 [MAC][I][eNB 0][PUSCH 0/a9d0] CC_id 0 Frame 14 subframeP 8 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 0) [MAC][I]Frame 14: Contention resolution timer 31/48 [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 14, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [MAC][I]Frame 14: Contention resolution timer 32/48 [MAC][I]Frame 15: Contention resolution timer 33/48 [MAC][I]Frame 15: Contention resolution timer 34/48 [MAC][I]Frame 15: Contention resolution timer 35/48 [MAC][I]Frame 15: Contention resolution timer 36/48 [MAC][I]Frame 15: Contention resolution timer 37/48 [MAC][I]Frame 15: Contention resolution timer 38/48 [MAC][I]Frame 15: Contention resolution timer 39/48 [MAC][I]Frame 15: Contention resolution timer 40/48 [MAC][I]Frame 15: Contention resolution timer 41/48 [MAC][I]Frame 15: Contention resolution timer 42/48 [MAC][I]Frame 16: Contention resolution timer 43/48 [MAC][I][eNB 0] CC_id 0 MAC CE_LCID 29 : ul_total_buffer = 57 (lcg increment 57) [MAC][I][eNB 0][PUSCH 5/1d0d] CC_id 0 Frame 16 subframeP 1 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 5) [MAC][I]Frame 16: Contention resolution timer 44/48 [MAC][I][eNB 0][PUSCH 6/1d0d] CC_id 0 Frame 16 subframeP 2 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 6) [MAC][I]Frame 16: Contention resolution timer 45/48 [MAC][I][eNB 0][PUSCH 7/1d0d] CC_id 0 Frame 16 subframeP 3 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 7) [MAC][I]Frame 16: Contention resolution timer 46/48 [MAC][I][eNB 0][PUSCH 0/1d0d] CC_id 0 Frame 16 subframeP 4 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 0) [MAC][I]Frame 16: Contention resolution timer 47/48 [MAC][E]Module id 1 Contention resolution timer expired, RA failed [PHY][E][UE 1] Random-access procedure fails, going back to PRACH, setting SIStatus = 0, discard temporary C-RNTI and State RRC_IDLE [MAC][I][eNB 0][PUSCH 1/1d0d] CC_id 0 Frame 16 subframeP 5 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 1) [MAC][I]subframe 5: Dropping Allocation for RNTI a9d0 (DCI 2/3) [MAC][I]DCI 0/3 : rnti ffff dci format 2, aggreg 4 nCCE 12 / 21 (num_pdcch_symbols 3) [MAC][I]DCI 1/3 : rnti 1d0d dci format 0, aggreg 8 nCCE 12 / 21 (num_pdcch_symbols 3) [MAC][I]DCI 2/3 : rnti a9d0 dci format 2, aggreg 8 nCCE 12 / 21 (num_pdcch_symbols 3) [MAC][W][eNB 0] frame 16 subframe 5, UE 0/a9d0 CC 0: not enough nCCE [MAC][I][eNB 0][PUSCH 2/1d0d] CC_id 0 Frame 16 subframeP 6 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 2) [MAC][I][eNB 0][PUSCH 2/a9d0] CC_id 0 Frame 16 subframeP 6 Scheduled UE 0 (mcs 0, first rb 4, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 2) [MAC][I][eNB 0][PUSCH 3/1d0d] CC_id 0 Frame 16 subframeP 7 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 3) [MAC][I][eNB 0][PUSCH 4/1d0d] CC_id 0 Frame 16 subframeP 8 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 4) [MAC][I][eNB 0][PUSCH 5/1d0d] CC_id 0 Frame 16 subframeP 9 Scheduled UE 1 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 5) [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 16, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [RRC][N][eNB 0] Frame 16: received a DCCH 1 message on SRB 1 with Size 53 from UE 1d0d [RRC][I][FRAME 00016][eNB][MOD 00][RNTI 1d0d] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00016][eNB][MOD 00][RNTI 1d0d] [RAPROC] Logical Channel UL-DCCH, processing RRCConnectionSetupComplete from UE (SRB1 Active) [RRC][I][FRAME 00016][eNB][MOD 00][RNTI 1d0d] UE State = RRC_CONNECTED [S1AP][I]Found usable eNB_ue_s1ap_id: 0x19f76d 1701741(10) [SCTP][I]Successfully sent 96 bytes on stream 1 for assoc_id 1 [PHY][I][UE 1] frame 16, subframe 6: received DCI 0 with RNTI=0 (C-RNTI:0, CBA_RNTI 0) and format 4! [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_DownlinkNASTransportIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3150) [RRC][I][eNB 0] Received S1AP_DOWNLINK_NAS: ue_initial_id 1, eNB_ue_s1ap_id 1701741 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 0, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 44 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 0 vtA 0 vtS 0 [MAC][E]scheduled retransmission in forbidden RBs [PHY][I][UE 1] frame 17, subframe 3: received DCI 0 with RNTI=0 (C-RNTI:0, CBA_RNTI 0) and format 4! [RRC][N][UE 0] Frame 17: received a DCCH 1 message on SRB 1 with Size 39 from eNB 0 [NAS][I][UE 0] Received NAS_DOWNLINK_DATA_IND: UEid 0, length 36 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_DATA_IND (211) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:412 EMMAS-SAP - Received AS data transfer indication (ueid=0, delivered=TRUE, length=36) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:312 EMMAS-SAP - Received EMM message (length=36) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/emm_msg.c:117 EMM-MSG - Message Type 0x52 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:387 EMMAS-SAP - Received Authentication Request message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:158 EMM-PROC - Authentication requested ksi type = native, ksi = 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:356 USIM-API - res(f2) :0xb6 0xec 0xf1 0x1e 0x38 0xa5 0x17 0x1a [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:357 USIM-API - ck(f3) :0xb2 0x57 0x57 0xba 0xe 0x95 0xcf 0x21 0x9c 0x78 0x8b 0x96 0x1b 0x8c 0x64 0xee [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:358 USIM-API - ik(f4) :0x5b 0x40 0xd0 0x6e 0xc5 0x1 0x56 0xf 0x73 0xf5 0xd1 0xb8 0x16 0x96 0x17 0x7d [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:360 USIM-API - ak(f5) : 95DB66DF3F28 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:371 USIM-API - Retrieved SQN 000000000000 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:393 USIM-API - Comparing the XMAC with the MAC included in AUTN Succeeded [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:274 EMM-PROC - Timer T3416 (-1) expires in 30 seconds [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:465 EMM_AS_NO_KEY_AVAILABLE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_SECURITY_RES (203) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1284 EMMAS-SAP - Send AS security response [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:772 EMMAS-SAP - Send Authentication Response message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:928 EMM-PROC _authentication_kasme INPUT CK 0xb2 0x57 0x57 0xba 0xe 0x95 0xcf 0x21 0x9c 0x78 0x8b 0x96 0x1b 0x8c 0x64 0xee [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:930 EMM-PROC _authentication_kasme INPUT IK 0x5b 0x40 0xd0 0x6e 0xc5 0x1 0x56 0xf 0x73 0xf5 0xd1 0xb8 0x16 0x96 0x17 0x7d [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:932 EMM-PROC _authentication_kasme INPUT AUTN 0x95 0xdb 0x66 0xdf 0x3f 0x28 0x80 0x0 0x3f 0x87 0x53 0x9a 0x5 0x66 0xe9 0x3f [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:934 EMM-PROC _authentication_kasme INPUT KASME LENGTH 32 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:964 EMM-PROC _authentication_kasme P0 MCC,MNC 00 F1 10 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:986 EMM-PROC _authentication_kasme input S to KFD (length 14)10 00 F1 10 00 03 95 DB 66 DF 3F 28 00 06 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:998 EMM-PROC KASME (l=32)0xc6 0xfb 0x5b 0x93 0x8f 0x47 0xe 0x3f 0x0 0x9f 0x6a 0xa4 0x9 0x55 0x27 0x74 0xb7 0x7e 0x5 0xf7 0xad 0x95 0x43 0x57 0xdd 0x26 0x6c 0xf1 0x21 0x63 0xa4 0x3d [NAS][I][UE] Received 1 events [PDCP][I][FRAME 00000][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 1, muiP 1, confirmP 0, mode 1 [RLC][I][FRAME 00000][ UE][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 19 Bytes, NB SDU 2 current_sdu_index=1 next_sdu_index=2 conf 0 mui 1 vtA 3 vtS 3 [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 17, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 17, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I]mode 0 [PHY][I][UE 1][RAPROC] Frame 18, Subframe 1 : Generating PRACH, preamble 55,PL 111, P0_PRACH 11, TARGET_RECEIVED_POWER -100 dBm, PRACH TDD Resource index 0, RA-RNTI 2 [PHY][I][UE 1][RAPROC] Frame 18, subframe 1: Generating PRACH (eNB 0) preamble index 55 for UL, TX power 11 dBm (PL 111 dB), l3msg [MAC][I]Received RRC_MAC_CCCH_DATA_REQ from TASK_RRC_UE: instance 2, frameP 18, eNB_index 0 [MAC][I][eNB 1][RAPROC] Frame 18 Received RAR (77|00.00.35.4c.78.ec) for preamble 55/55 [PHY][I][UE 1] AbsoluteSubFrame 18.5, received (rar) timing_advance 0 [PHY][I][UE 1][RAPROC] Frame 19, Subframe 1 Generating (RRCConnectionRequest) Msg3 (nb_rb 2, first_rb 1, round 0, rvidx 0) Msg3: 20.6.1f|51.46.9d.a4.20.26 [PHY][I][UE 1][RAPROC] AbsSubframe 19.1: Msg3 (2 PRBs) Po_PUSCH 17 dBm (-10000,301,100*PL=11200,0,200) [MAC][I]Frame 19: Contention resolution timer 0/48 [MAC][I]Frame 19: Contention resolution timer 1/48 [MAC][I]Frame 19: Contention resolution timer 2/48 [PHY][I][eNB 0][RAPROC] Frame 19 Terminating ra_proc for harq 7, UE 2 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 19, Received CCCH: 51.46.9d.a4.20.26, Terminating RA procedure for UE rnti 78ec [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 19 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 2 rnti 78ec [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 19 Added user with rnti 78ec => UE 2 [MAC][I][eNB 0] frame 19 subfarme 5, UE 2: not configured, skipping UE scheduling [RRC][I][FRAME 00019][eNB][MOD 00][RNTI 78ec] Received RRC_MAC_CCCH_DATA_IND [RRC][W]new UE rnti 78ec (coming with random value) is already there as UE a9d0, removing 78ec from MAC/PHY MAC: remove UE 2 rnti 78ec [MAC][I]Removing UE 2 from Primary CC_id 0 (rnti 78ec) [MAC][I]Frame 19: Contention resolution timer 3/48 [MAC][I]Frame 19: Contention resolution timer 4/48 [MAC][I]Frame 19: Contention resolution timer 5/48 [MAC][I][eNB 0][PUSCH 2/a9d0] CC_id 0 Frame 19 subframeP 8 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 2) [MAC][I]Frame 19: Contention resolution timer 6/48 [PHY][I][UE 1][PUSCH 7][RAPROC] Frame 19 subframe 5 Msg3 PHICH, received ACK (-776) nseq 1, ngroup 0 [MAC][I]Frame 19: Contention resolution timer 7/48 [MAC][I]Frame 20: Contention resolution timer 8/48 [RRC][N][eNB 0] Frame 19: received a DCCH 1 message on SRB 1 with Size 14 from UE 1d0d [RRC][I][FRAME 00019][eNB][MOD 00][RNTI 1d0d] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I]Successfully sent 59 bytes on stream 1 for assoc_id 1 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 39 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_DownlinkNASTransportIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3150) [RRC][I][eNB 0] Received S1AP_DOWNLINK_NAS: ue_initial_id 1, eNB_ue_s1ap_id 1701741 [MAC][I]Frame 20: Contention resolution timer 9/48 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 0, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 21 Bytes, NB SDU 2 current_sdu_index=1 next_sdu_index=2 conf 0 mui 0 vtA 2 vtS 2 [MAC][I]Frame 20: Contention resolution timer 10/48 [MAC][I]Frame 20: Contention resolution timer 11/48 [MAC][I]Frame 20: Contention resolution timer 12/48 [MAC][I]Frame 20: Contention resolution timer 13/48 [MAC][I]Frame 20: Contention resolution timer 14/48 [RRC][N][UE 0] Frame 20: received a DCCH 1 message on SRB 1 with Size 16 from eNB 0 [NAS][I][UE 0] Received NAS_DOWNLINK_DATA_IND: UEid 0, length 13 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_DATA_IND (211) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:412 EMMAS-SAP - Received AS data transfer indication (ueid=0, delivered=TRUE, length=13) [NAS][W] /root/openairinterface5g/openair3/NAS/COMMON/API/NETWORK/nas_message.c:328 MAC failure but continue due to EIA0 selected [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:312 EMMAS-SAP - Received EMM message (length=7) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/emm_msg.c:117 EMM-MSG - Message Type 0x5d [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:469 EMMAS-SAP - Received Security Mode Command message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:475 Execute the security mode control procedure initiated by the network: imeisvrequest 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:153 EMM-PROC - Security mode control requested (ksi=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:463 EMM-PROC - Delete authentication data RAND and RES [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:187 EMM-PROC - Update the non-current EPS security context seea=0 seia=2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:203 EMM-PROC - Update the non-current EPS security context knas_enc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:418 _security_knas_enc with algo dist 1 algo id 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:217 EMM-PROC - Update the non-current EPS security context knas_int [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:444 _security_knas_int with algo dist 2 algo id 2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:231 EMM-PROC - Update the non-current EPS security context kenb [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:476 _security_kenb with count= 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:243 EMM-PROC - NAS security mode command accepted by the UE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:259 EMM-PROC - Update Current security context [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:434 EPS security context exists is new 1 KSI 0 SQN 0 count 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:436 knas_int 0xe8 0x14 0x87 0x3e 0xe5 0x2a 0x7f 0x46 0x9e 0x7b 0x44 0xf6 0x9c 0xf4 0xc5 0x38 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:438 knas_enc 0x75 0x9a 0x71 0x94 0xc5 0xc8 0x3e 0x47 0x89 0x8 0x59 0xee 0xb 0x46 0x19 0xfc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:440 kasme 0xc6 0xfb 0x5b 0x93 0x8f 0x47 0xe 0x3f 0x0 0x9f 0x6a 0xa4 0x9 0x55 0x27 0x74 0xb7 0x7e 0x5 0xf7 0xad 0x95 0x43 0x57 0xdd 0x26 0x6c 0xf1 0x21 0x63 0xa4 0x3d [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:461 EPS security context exists knas_enc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_SECURITY_RES (203) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1284 EMMAS-SAP - Send AS security response [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:853 EMMAS-SAP - Send Security Mode Complete message [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/SecurityModeComplete.c:79 SECURITY MODE COMMAND COMPLETE: presencemask: 0 [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/SecurityModeComplete.c:93 SECURITY MODE COMMAND COMPLETE done !!! Byte length: 11, Zero bits: 0 m: 000000000000000000075e Key:e814873ee52a7f469e7b44f69cf4c538 Message:00075e out: ef5af50e368ea269d7506cd18bdae47f [NAS][I][UE] Received 1 events [PDCP][I][FRAME 00000][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 1, muiP 2, confirmP 0, mode 1 [RLC][I][FRAME 00000][ UE][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 16 Bytes, NB SDU 3 current_sdu_index=2 next_sdu_index=3 conf 0 mui 2 vtA 4 vtS 4 [MAC][I]Frame 20: Contention resolution timer 15/48 [MAC][I]Frame 20: Contention resolution timer 16/48 [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 20, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 1] Frame 20, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [MAC][I]Frame 20: Contention resolution timer 17/48 [MAC][I]Frame 21: Contention resolution timer 18/48 [MAC][I]Frame 21: Contention resolution timer 19/48 [MAC][I]Frame 21: Contention resolution timer 20/48 [MAC][I]Frame 21: Contention resolution timer 21/48 [MAC][I]Frame 21: Contention resolution timer 22/48 [MAC][I]Frame 21: Contention resolution timer 23/48 [MAC][I]Frame 21: Contention resolution timer 24/48 [MAC][I]Frame 21: Contention resolution timer 25/48 [MAC][I]Frame 21: Contention resolution timer 26/48 [RRC][I]Removing UE a9d0 instance [RRC][W][eNB 0] Removing UE RNTI a9d0 MAC: remove UE 0 rnti a9d0 [MAC][I]Removing UE 0 from Primary CC_id 0 (rnti a9d0) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a9d0] Removed UE context [S1AP][W]Failed to find ue context associated with eNB ue s1ap id: 0 [S1AP][E]Failed to find ue context associated with eNB ue s1ap id: 0 [MAC][I]Frame 21: Contention resolution timer 27/48 [MAC][I]Frame 22: Contention resolution timer 28/48 [MAC][I]Frame 22: Contention resolution timer 29/48 [MAC][I]Frame 22: Contention resolution timer 30/48 [MAC][I]Frame 22: Contention resolution timer 31/48 [MAC][I]Frame 21: Contention resolution timer 32/48 [MAC][I]Frame 21: Contention resolution timer 33/48 [MAC][I]Frame 21: Contention resolution timer 34/48 [MAC][I]Frame 21: Contention resolution timer 35/48 [MAC][I]Frame 21: Contention resolution timer 36/48 [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 21, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 22, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [MAC][I]Frame 21: Contention resolution timer 37/48 [MAC][I]Frame 22: Contention resolution timer 38/48 [RRC][N][eNB 0] Frame 22: received a DCCH 1 message on SRB 1 with Size 11 from UE 1d0d [RRC][I][FRAME 00022][eNB][MOD 00][RNTI 1d0d] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I]Successfully sent 56 bytes on stream 1 for assoc_id 1 [MAC][I]Frame 22: Contention resolution timer 39/48 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 200 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_InitialContextSetupRequestIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:1003) [MAC][I]Frame 22: Contention resolution timer 40/48 [S1AP][I]Received NAS message with the E_RAB setup procedure [RRC][I][eNB 0] Received S1AP_INITIAL_CONTEXT_SETUP_REQ: ue_initial_id 1, eNB_ue_s1ap_id 1701741, nb_of_e_rabs 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d] rrc_eNB_process_GTPV1U_CREATE_TUNNEL_RESP tunnel (1612692225, 1612692225) bearer UE context index 0, msg index 0, id 5, gtp addr len 4 [RRC][I][eNB 0][UE 1d0d] Selected security algorithms (0x7fefe9fffc34): 0, 2, changed [RRC][I][eNB 0][UE 1d0d] Saved security key 128F0FCCB50EA42F61653D056B9E26E0AC5DBFCBAB87EFED49F70B09739063A1 KeNB:128f0fccb50ea42f61653d056b9e26e0ac5dbfcbab87efed49f70b09739063a1 KRRCenc:9b6387c58332b7ef5431b70a6ddbe7f4401166b5d1c111168cce3c60b49285c8 KRRCint:e2c81638a67cfe6eb2f35e2a368627f21588feeea79020fb371fbada474c2291 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d] Logical Channel DL-DCCH, Generate SecurityModeCommand (bytes 3) [MAC][I]Frame 22: Contention resolution timer 41/48 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 0, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 8 Bytes, NB SDU 3 current_sdu_index=2 next_sdu_index=3 conf 0 mui 0 vtA 3 vtS 3 [MAC][I]Frame 22: Contention resolution timer 42/48 [MAC][I]Frame 22: Contention resolution timer 43/48 [MAC][I]Frame 22: Contention resolution timer 44/48 [MAC][I]Frame 22: Contention resolution timer 45/48 [MAC][I]Frame 22: Contention resolution timer 46/48 [RRC][N][UE 0] Frame 23: received a DCCH 1 message on SRB 1 with Size 3 from eNB 0 [RRC][I][UE 0] Received securityModeCommand (eNB 0) [RRC][I][UE 0] Frame 23: Receiving from SRB1 (DL-DCCH), Processing securityModeCommand (eNB 0) [RRC][I][UE 0] Security algorithm is set to eea0 [RRC][I][UE 0] Integrity protection algorithm is set to eia2 [RRC][I][UE 0] Frame 23: Receiving from SRB1 (DL-DCCH), encoding securityModeComplete (eNB 0) [PDCP][I][FRAME 00023][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 1, muiP 3, confirmP 0, mode 1 [RLC][I][FRAME 00023][ UE][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 7 Bytes, NB SDU 4 current_sdu_index=3 next_sdu_index=4 conf 0 mui 3 vtA 5 vtS 5 [MAC][I]Frame 22: Contention resolution timer 47/48 [MAC][E]Module id 1 Contention resolution timer expired, RA failed [PHY][E][UE 1] Random-access procedure fails, going back to PRACH, setting SIStatus = 0, discard temporary C-RNTI and State RRC_IDLE [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 23, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I]mode 0 [PHY][I][UE 1][RAPROC] Frame 24, Subframe 1 : Generating PRACH, preamble 5,PL 111, P0_PRACH 11, TARGET_RECEIVED_POWER -100 dBm, PRACH TDD Resource index 0, RA-RNTI 2 [PHY][I][UE 1][RAPROC] Frame 24, subframe 1: Generating PRACH (eNB 0) preamble index 5 for UL, TX power 11 dBm (PL 111 dB), l3msg [MAC][I]Received RRC_MAC_CCCH_DATA_REQ from TASK_RRC_UE: instance 2, frameP 24, eNB_index 0 [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 25, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 24, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [RRC][N][eNB 0] Frame 25: received a DCCH 1 message on SRB 1 with Size 2 from UE 1d0d [MAC][I][eNB 0][DLSCH] Frame 26 Generate header for UE_id 1 on CC_id 0: sdu_length_total 2, num_sdus 1, sdu_lengths[0] 2, sdu_lcids[0] 1 => payload offset 5,timing advance value : -2, padding 2,post_padding 0,(mcs 1, TBS 7, nb_rb 2),header_dcch 1, header_dtch 0 [RRC][I][FRAME 00025][eNB][MOD 00][RNTI 1d0d] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00025][eNB][MOD 00][RNTI 1d0d] received securityModeComplete on UL-DCCH 1 from UE [RRC][I][FRAME 00025][eNB][MOD 00][RNTI 1d0d] Logical Channel DL-DCCH, Generate UECapabilityEnquiry (bytes 3) [PDCP][I][FRAME 00025][eNB][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 1, confirmP 0, mode 1 [RLC][I][FRAME 00025][eNB][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 8 Bytes, NB SDU 4 current_sdu_index=3 next_sdu_index=4 conf 0 mui 1 vtA 4 vtS 4 [RRC][N][UE 0] Frame 26: received a DCCH 1 message on SRB 1 with Size 3 from eNB 0 [RRC][I][UE 0] Received Capability Enquiry (eNB 0) [RRC][I][UE 0] Frame 26: Receiving from SRB1 (DL-DCCH), Processing UECapabilityEnquiry (eNB 0) [PDCP][I][FRAME 00026][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 1, muiP 4, confirmP 0, mode 1 [RLC][I][FRAME 00026][ UE][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 24 Bytes, NB SDU 5 current_sdu_index=4 next_sdu_index=5 conf 0 mui 4 vtA 6 vtS 6 [PHY][I][UE 1] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 1] Frame 26, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I][UE 0] subframe 5: Found rnti ffff, format 1A, dci_cnt 0 [PHY][I][UE 0] Frame 26, subframe 5 : Generate UE DLSCH SI_RNTI format 1A [PHY][I]mode 0 [PHY][I][UE 1][RAPROC] Frame 28, Subframe 1 : Generating PRACH, preamble 32,PL 112, P0_PRACH 14, TARGET_RECEIVED_POWER -98 dBm, PRACH TDD Resource index 0, RA-RNTI 2 [PHY][I][UE 1][RAPROC] Frame 28, subframe 1: Generating PRACH (eNB 0) preamble index 32 for UL, TX power 14 dBm (PL 112 dB), l3msg [MAC][I][eNB 1][RAPROC] Frame 28 Received RAR (60|00.00.35.4c.13.bd) for preamble 32/32 [PHY][I][UE 1] AbsoluteSubFrame 28.5, received (rar) timing_advance 0 [RRC][N][eNB 0] Frame 28: received a DCCH 1 message on SRB 1 with Size 19 from UE 1d0d [RRC][I][FRAME 00028][eNB][MOD 00][RNTI 1d0d] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00028][eNB][MOD 00][RNTI 1d0d] received ueCapabilityInformation on UL-DCCH 1 from UE [RRC][I]got UE capabilities for UE 1d0d [RRC][I]RRCConnectionReconfiguration Encoded 1112 bits (139 bytes) [RRC][I][eNB 0] Frame 28, Logical Channel DL-DCCH, Generate RRCConnectionReconfiguration (bytes 139, UE id 1d0d) [SCTP][I]Successfully sent 46 bytes on stream 1 for assoc_id 1 [PHY][I][UE 1][RAPROC] Frame 29, Subframe 1 Generating (RRCConnectionRequest) Msg3 (nb_rb 2, first_rb 1, round 0, rvidx 0) Msg3: 20.6.1f|51.46.9d.a4.20.26 [PHY][I][UE 1][RAPROC] AbsSubframe 29.1: Msg3 (2 PRBs) Po_PUSCH 19 dBm (-10000,301,100*PL=11200,0,400) [PDCP][I][FRAME 00028][eNB][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 2, confirmP 0, mode 1 [RLC][I][FRAME 00028][eNB][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 144 Bytes, NB SDU 5 current_sdu_index=4 next_sdu_index=5 conf 0 mui 2 vtA 5 vtS 5 [MAC][I]Frame 29: Contention resolution timer 0/48 [MAC][I]Frame 29: Contention resolution timer 1/48 [MAC][I]Frame 29: Contention resolution timer 2/48 [PHY][I][eNB 0][RAPROC] Frame 29 Terminating ra_proc for harq 3, UE 0 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 29, Received CCCH: 51.46.9d.a4.20.26, Terminating RA procedure for UE rnti 13bd [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 29 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti 13bd [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 29 Added user with rnti 13bd => UE 0 [MAC][I][eNB 0] frame 29 subfarme 5, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00029][eNB][MOD 00][RNTI 13bd] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00029][eNB][MOD 00][RNTI 13bd] Accept new connection from UE random UE identity (0x242da6914000000) MME code 0 TMSI 0 cause 3 [MAC][I][CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (13bd) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7fef68004470 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 2 [RRC][I][FRAME 00029][eNB][MOD 00][RNTI 13bd] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00029][eNB][MOD 00][RNTI 13bd]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00029][eNB][MOD 00][RNTI 13bd][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00029][eNB][MOD 00][RNTI 13bd] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I]Frame 29: Contention resolution timer 3/48 [MAC][I][eNB 0] frame 29 subfarme 6, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7fef68004470 for UE 0 [RLC][I][FRAME 00029][eNB][MOD 00][RNTI 13bd][SRB AM 01][CONFIGURE] max_retx_threshold 4 poll_pdu 4 poll_byte 65535 t_poll_retransmit 80 t_reordering 35 t_status_prohibit 0 [RRC][N][UE 0] Frame 29: received a DCCH 1 message on SRB 1 with Size 139 from eNB 0 [MAC][I]Frame 29: Contention resolution timer 4/48 [RRC][I][UE 0] Frame 29: Receiving from SRB1 (DL-DCCH), Processing RRCConnectionReconfiguration (eNB 0) [RRC][I]Radio Resource Configuration is present [RRC][I]Save physicalConfigDedicated if present [RRC][I]Update pdsch_ConfigDedicated config [RRC][I]Update pusch_ConfigDedicated config [RRC][I]Update pucch_ConfigDedicated config [RRC][I]Update cqi_ReportConfig config (size=48,48) [RRC][I]Update cqi_ReportPeriodic config (size=152,152) [RRC][I]Update schedulingRequestConfig config [RRC][I]Keep old config for soundingRS_UL_ConfigDedicated [RRC][I]Update antennaInfo config [PHY][I]New Transmission Mode 1 [PHY][I]Configured Transmission Mode 1 [RRC][I]Update uplinkPowerControlDedicated config [RRC][I]Update tpc_PDCCH_ConfigPUCCH config [RRC][I]Update tpc_PDCCH_ConfigPUSCH config [PDCP][N][FRAME 00029][ UE][MOD 00][RNTI 1d0d][SRB 02] Action ADD LCID 2 (SRB id 2) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d] [SRB 2] rrc_rlc_add_rlc SRB [MAC][I][eNB 0] frame 29 subfarme 7, UE 0: not configured, skipping UE scheduling [RLC][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d][SRB AM 02][CONFIGURE] max_retx_threshold 32 poll_pdu 8 poll_byte 16960 t_poll_retransmit 15 t_reordering 35 t_status_prohibit 10 [RRC][I][UE 0], CONFIG_SRB2 2 corresponding to eNB_index 0 [RRC][I]Applying Explicit SRB2 logicalChannelConfig [RRC][I][FRAME 00029][RRC_UE][MOD 00][][--- MAC_CONFIG_REQ (SRB2 eNB 0) --->][MAC_UE][MOD 00][] [MAC][I][CONFIG][UE 0] Configuring MAC/PHY from eNB 0 [MAC][I][CONFIG][UE 0] Applying RRC logicalChannelConfig from eNB0 [MAC][I][CONFIG][UE0] Applying RRC macMainConfig from eNB0 [PHY][I]Transmission Mode 2 [PHY][I]Disable SIB MIB decoding [PHY][I]C-RNTI 1d0d 1d0d [RRC][I][UE 0] default DRB = 1 [PDCP][N][FRAME 00029][ UE][MOD 00][RNTI 1d0d][DRB 01] Action ADD LCID 3 (DRB id 1) configured with SN size 12 bits and RLC AM [RLC][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d] [DRB 1] rrc_rlc_add_rlc DRB [RLC][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d][DRB AM 01][CONFIGURE] max_retx_threshold 8 poll_pdu 16 poll_byte 65535 t_poll_retransmit 50 t_reordering 35 t_status_prohibit 25 [RRC][I][UE 0] Frame 29: processing RRCConnectionReconfiguration: reconfiguring DRB 1/LCID 3 [RRC][I][FRAME 00029][RRC_UE][MOD 00][][--- MAC_CONFIG_REQ (DRB 1 eNB 0) --->][MAC_UE][MOD 00][] [MAC][I][CONFIG][UE 0] Configuring MAC/PHY from eNB 0 [MAC][I][CONFIG][UE 0] Applying RRC logicalChannelConfig from eNB0 [MAC][I][CONFIG][UE0] Applying RRC macMainConfig from eNB0 [PHY][I]Transmission Mode 2 [PHY][I]Disable SIB MIB decoding [PHY][I]C-RNTI 1d0d 1d0d [RRC][I][UE 0] State = RRC_CONNECTED (eNB 0) [RRC][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d] Logical Channel UL-DCCH (SRB1), Generating RRCConnectionReconfigurationComplete (bytes 2, eNB_index 0) [RRC][I][UE 0] State = RRC_RECONFIGURED (eNB 0) [NAS][I][UE 0] Received NAS_CONN_ESTABLI_CNF: errCode 1, length 95 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_ESTABLISH_CNF (206) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:488 EMMAS-SAP - Received AS connection establish confirm Byte length: 98, Zero bits: 0 m: 00000001040000000107420149062000f1100001003a5201c101090a036c7465026d64026a7005011900000227228080211002000010810608080808830608080404000d0408080808000d0408080404500bf600f110000201ec00460b5949640101 Key:e814873ee52a7f469e7b44f69cf4c538 Message:0107420149062000f1100001003a5201c101090a036c7465026d64026a7005011900000227228080211002000010810608080808830608080404000d0408080808000d0408080404500bf600f110000201ec00460b5949640101 out: 053669898ab57766028c45dbe945506f [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/emm_msg.c:117 EMM-MSG - Message Type 0x42 [NAS][W] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/AttachAccept.c:197 DECODED 87 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:135 EMMAS-SAP - Received Attach Accept message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:352 EMM-PROC - EPS attach accepted by the network [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:355 EMM-PROC - Stop timer T3410 (-1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_sap.c:155 ESM-SAP - Received primitive ESM_DEFAULT_EPS_BEARER_CONTEXT_ACTIVATE_REQ (1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_recv.c:290 ESM-SAP - Received Activate Default EPS Bearer Context Request message (pti=1, ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:372 ESM-PROC - PDN connectivity accepted by the network (pti=1) APN = 03"ltemdjp", IP address = 25.0.0.2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_pt.c:383 ESM-FSM - Status of procedure transaction 1 changed: PROCEDURE TRANSACTION PENDING ===> PROCEDURE TRANSACTION INACTIVE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:774 ESM-PROC - Update PDN connection (pid=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/DefaultEpsBearerContextActivation.c:103 ESM-PROC - Default EPS bearer context activation requested by the network (ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr.c:219 ESM-FSM - EPS bearer context 5 assigned [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr_context.c:118 ESM-PROC - Create new default EPS bearer context (ebi=5) for PDN connection (pid=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr_context.c:288 ESM-PROC - executing ifconfig oip1 25.0.0.2 netmask 255.0.0.0 broadcast 25.255.255.255 up && ip rule add from 25.0.0.2/32 table 201 && ip rule add to 25.0.0.2/32 table 201 && ip route add default dev oip1 table 201 [PDCP][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 1, muiP 5, confirmP 0, mode 1 [RLC][I][FRAME 00029][ UE][MOD 00][RNTI 1d0d][SRB AM 01] RLC_AM_DATA_REQ size 7 Bytes, NB SDU 6 current_sdu_index=5 next_sdu_index=6 conf 0 mui 5 vtA 7 vtS 7 [MAC][I]Frame 29: Contention resolution timer 5/48 [MAC][I][eNB 0] frame 29 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 29: Contention resolution timer 6/48 [MAC][I][eNB 0] frame 29 subfarme 9, UE 0: not configured, skipping UE scheduling [PHY][I][UE 1][PUSCH 3][RAPROC] Frame 29 subframe 5 Msg3 PHICH, received ACK (-753) nseq 1, ngroup 0 [MAC][I]Frame 29: Contention resolution timer 7/48 [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 30, subframeP 0: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 13bd) [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 30 subframeP 0 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][eNB 0] frame 30 subfarme 0, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 30: Contention resolution timer 8/48 [MAC][I][eNB 0] frame 30 subfarme 1, UE 0: not configured, skipping UE scheduling [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_send.c:290 ESM-SAP - Send Activate Default EPS Bearer Context Accept message (pti=0, ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/ESM/MSG/esm_msg.c:269 ESM-MSG - Encoded ESM message header (3) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/DefaultEpsBearerContextActivation.c:188 ESM-PROC - Default EPS bearer context activation accepted by the UE (ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr.c:321 ESM-FSM - Status of EPS bearer context 5 changed: BEARER CONTEXT INACTIVE ===> BEARER CONTEXT ACTIVE [NAS][E] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:308 USR-API - send() failed, Invalid argument [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:434 EPS security context exists is new 0 KSI 0 SQN 1 count 16777216 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:436 knas_int 0xe8 0x14 0x87 0x3e 0xe5 0x2a 0x7f 0x46 0x9e 0x7b 0x44 0xf6 0x9c 0xf4 0xc5 0x38 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:438 knas_enc 0x75 0x9a 0x71 0x94 0xc5 0xc8 0x3e 0x47 0x89 0x8 0x59 0xee 0xb 0x46 0x19 0xfc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:440 kasme 0xc6 0xfb 0x5b 0x93 0x8f 0x47 0xe 0x3f 0x0 0x9f 0x6a 0xa4 0x9 0x55 0x27 0x74 0xb7 0x7e 0x5 0xf7 0xad 0x95 0x43 0x57 0xdd 0x26 0x6c 0xf1 0x21 0x63 0xa4 0x3d [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:461 EPS security context exists knas_enc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_DATA_REQ (210) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1075 EMMAS-SAP - Send AS data transfer request [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:329 EMMAS-SAP - Send Attach Complete message Byte length: 16, Zero bits: 0 m: 000000010000000001074300035200c2 Key:e814873ee52a7f469e7b44f69cf4c538 Message:01074300035200c2 out: e8bd3cfc0022fb9437ece2d028184d12 [NAS][I][UE] Received 1 events [PDCP][I][FRAME 00000][ UE][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 1, rb_id 2, muiP 6, confirmP 0, mode 1 [MAC][I]Frame 30: Contention resolution timer 9/48 [RLC][I][FRAME 00000][ UE][MOD 00][RNTI 1d0d][SRB AM 02] RLC_AM_DATA_REQ size 21 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 6 vtA 0 vtS 0 [MAC][I][eNB 0] frame 30 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 30: Contention resolution timer 10/48 [MAC][I][eNB 0] frame 30 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I]Frame 30: Contention resolution timer 11/48 [MAC][I][eNB 0] frame 30 subfarme 4, UE 0: not configured, skipping UE scheduling [PHY][I][UE 1] Frame 30, subframe 0: Received DCI with CRNTI 13bd => Mode PUSCH [MAC][I][UE 1][RAPROC] Frame 30 : received contention resolution msg: 51.46.9d.a4.20.26, Terminating RA procedure [MAC][I][UE 1][RAPROC] Frame 30 : Clearing RA_active flag [MAC][I][UE 1][RAPROC] Frame 30 : Clearing contention resolution timer [PHY][I][UE 1][RAPROC] Random-access procedure succeeded. Set C-RNTI = Temporary C-RNTI [RRC][I][UE1][RAPROC] Frame 30 : Logical Channel DL-CCCH (SRB0), Received RRCConnectionSetup RNTI 13bd [RRC][I]Save physicalConfigDedicated if present [RRC][I]Init physicalConfigDedicated UE_rrc_inst to radioResourceConfigDedicated->physicalConfigDedicated [PDCP][N][FRAME 00030][ UE][MOD 01][RNTI 13bd][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00030][ UE][MOD 01][RNTI 13bd] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 30, subframeP 5: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 13bd fsf 30/5, let's configure it [MAC][I][eNB 0][RAPROC] CC_id 0 Frame 30, subframeP 5 : Msg4 acknowledged [MAC][I][eNB 0][PUSCH 5/13bd] CC_id 0 Frame 30 subframeP 5 Scheduled UE 0 (mcs 0, first rb 4, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 5) [RLC][I][FRAME 00030][ UE][MOD 01][RNTI 13bd][SRB AM 01][CONFIGURE] max_retx_threshold 4 poll_pdu 4 poll_byte 65535 t_poll_retransmit 80 t_reordering 35 t_status_prohibit 0 [RRC][I][UE 1], CONFIG_SRB1 1 corresponding to eNB_index 0 [RRC][I][FRAME 00030][RRC_UE][MOD 01][][--- MAC_CONFIG_REQ (SRB1 eNB 0) --->][MAC_UE][MOD 01][] [MAC][I][CONFIG][UE 1] Configuring MAC/PHY from eNB 0 [MAC][I][CONFIG][UE 1] Applying RRC logicalChannelConfig from eNB0 [PHY][I]Transmission Mode 2 [PHY][I]Disable SIB MIB decoding [PHY][I]C-RNTI 13bd 13bd [RRC][I][UE 1] State = RRC_CONNECTED (eNB 0) [RRC][I][UE 1][RAPROC] Frame 30 : Logical Channel UL-DCCH (SRB1), Generating RRCConnectionSetupComplete (bytes53, eNB 0) [PDCP][I][FRAME 00030][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 1, muiP 7, confirmP 0, mode 1 [RLC][I][FRAME 00030][ UE][MOD 01][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 58 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 7 vtA 0 vtS 0 [RRC][N][eNB 0] Frame 30: received a DCCH 1 message on SRB 1 with Size 2 from UE 1d0d [RRC][I][FRAME 00030][eNB][MOD 00][RNTI 1d0d] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00030][eNB][MOD 00][RNTI 1d0d] UE State = RRC_RECONFIGURED (default DRB, xid 1) [PDCP][N][FRAME 00030][eNB][MOD 00][RNTI 1d0d][SRB 02] Action ADD LCID 2 (SRB id 2) configured with SN size 5 bits and RLC AM [PDCP][N][FRAME 00030][eNB][MOD 00][RNTI 1d0d][DRB 01] Action ADD LCID 3 (DRB id 1) configured with SN size 12 bits and RLC AM [RLC][I][FRAME 00030][eNB][MOD 00][RNTI 1d0d] [SRB 2] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00030][eNB][MOD 00][RNTI 1d0d][SRB AM 02][CONFIGURE] max_retx_threshold 32 poll_pdu 8 poll_byte 16960 t_poll_retransmit 15 t_reordering 35 t_status_prohibit 10 [RLC][I][FRAME 00030][eNB][MOD 00][RNTI 1d0d] [DRB 1] rrc_rlc_add_rlc DRB [RLC][I][FRAME 00030][eNB][MOD 00][RNTI 1d0d][DRB AM 01][CONFIGURE] max_retx_threshold 8 poll_pdu 16 poll_byte 65535 t_poll_retransmit 50 t_reordering 35 t_status_prohibit 25 [RRC][I][eNB 0] Frame 30 CC 0 : SRB2 is now active [RRC][I][eNB 0] Frame 30 : Logical Channel UL-DCCH, Received RRCConnectionReconfigurationComplete from UE rnti 1d0d, reconfiguring DRB 1/LCID 3 [RRC][I][eNB 0] Frame 30 : Logical Channel UL-DCCH, Received RRCConnectionReconfigurationComplete from UE 0, reconfiguring DRB 1/LCID 3 [MAC][I][CONFIG][eNB 0/0] Configuring MAC/PHY for UE 1 (1d0d) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7fef68023ef0 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 2 [S1AP][I]initial_ctxt_resp_p: e_rab ID 5, enb_addr 10.20.0.131, SIZE 4 [SCTP][I]Successfully sent 40 bytes on stream 1 for assoc_id 1 [MAC][E]scheduled retransmission in forbidden RBs [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7fef68023ef0 for UE 1 [MAC][I][eNB 0] CC_id 0 MAC CE_LCID 29 : ul_total_buffer = 57 (lcg increment 57) [RRC][N][eNB 0] Frame 31: received a DCCH 2 message on SRB 2 with Size 16 from UE 1d0d [MAC][I][eNB 0][PUSCH 5/13bd] CC_id 0 Frame 32 subframeP 1 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 5) [MAC][I][eNB 0], Frame 32, DCCH1->DLSCH, CC_id 0, Requesting 125 bytes from RLC (RRC message) [RRC][I][FRAME 00031][eNB][MOD 00][RNTI 1d0d] Received on DCCH 2 RRC_DCCH_DATA_IND [SCTP][I]Successfully sent 61 bytes on stream 1 for assoc_id 1 [MAC][I][eNB 0][PUSCH 6/13bd] CC_id 0 Frame 32 subframeP 2 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 6) [MAC][I][eNB 0][PUSCH 7/13bd] CC_id 0 Frame 32 subframeP 3 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 7) [MAC][I][eNB 0][PUSCH 0/13bd] CC_id 0 Frame 32 subframeP 4 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 0) [MAC][I][eNB 0][PUSCH 1/13bd] CC_id 0 Frame 32 subframeP 5 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 1) [MAC][I][eNB 0][PUSCH 2/13bd] CC_id 0 Frame 32 subframeP 6 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 2) [MAC][I][eNB 0][PUSCH 3/13bd] CC_id 0 Frame 32 subframeP 7 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 3) [MAC][I][eNB 0][PUSCH 4/13bd] CC_id 0 Frame 32 subframeP 8 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 4) [MAC][I][eNB 0][PUSCH 5/13bd] CC_id 0 Frame 32 subframeP 9 Scheduled UE 0 (mcs 9, first rb 1, nb_rb 3, rb_table_index 2, TBS 57, harq_pid 5) [RRC][N][eNB 0] Frame 32: received a DCCH 1 message on SRB 1 with Size 53 from UE 13bd [RRC][I][FRAME 00032][eNB][MOD 00][RNTI 13bd] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00032][eNB][MOD 00][RNTI 13bd] [RAPROC] Logical Channel UL-DCCH, processing RRCConnectionSetupComplete from UE (SRB1 Active) [RRC][I][FRAME 00032][eNB][MOD 00][RNTI 13bd] UE State = RRC_CONNECTED [S1AP][I]Found usable eNB_ue_s1ap_id: 0x2decc3 3009731(10) [SCTP][I]Successfully sent 96 bytes on stream 1 for assoc_id 1 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_DownlinkNASTransportIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3150) [RRC][I][eNB 0] Received S1AP_DOWNLINK_NAS: ue_initial_id 0, eNB_ue_s1ap_id 1701741 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 2, muiP 3, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 1d0d][SRB AM 02] RLC_AM_DATA_REQ size 44 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 3 vtA 0 vtS 0 [MAC][I][eNB 0], Frame 35, DCCH1->DLSCH, CC_id 0, Requesting 125 bytes from RLC (RRC message) [OSA][E]Mismatch found in integrity for algorithm 2, got 96.6b.7a.29, expecting 00.00.00.00 [PDCP][E][OSA][RB 2] UE failed to validate MAC-I of incoming PDU [RRC][N][UE 0] Frame 35: received a DCCH 2 message on SRB 2 with Size 39 from eNB 0 [RRC][E][UE 0] Frame 35: Received message on DL-DCCH (SRB2), should not have ... [MAC][I][eNB 0], Frame 36, DCCH1->DLSCH, CC_id 0, Requesting 125 bytes from RLC (RRC message) [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_DownlinkNASTransportIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3150) [RRC][I][eNB 0] Received S1AP_DOWNLINK_NAS: ue_initial_id 2, eNB_ue_s1ap_id 3009731 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 3, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 44 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 3 vtA 0 vtS 0 [RRC][N][UE 1] Frame 40: received a DCCH 1 message on SRB 1 with Size 39 from eNB 0 [NAS][I][UE 1] Received NAS_DOWNLINK_DATA_IND: UEid 1, length 36 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_DATA_IND (211) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:412 EMMAS-SAP - Received AS data transfer indication (ueid=1, delivered=TRUE, length=36) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:312 EMMAS-SAP - Received EMM message (length=36) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/emm_msg.c:117 EMM-MSG - Message Type 0x52 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:387 EMMAS-SAP - Received Authentication Request message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:158 EMM-PROC - Authentication requested ksi type = native, ksi = 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:356 USIM-API - res(f2) :0xaa 0xd8 0xec 0x51 0x79 0xaf 0x2c 0xe8 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:357 USIM-API - ck(f3) :0xa0 0x23 0x38 0xa7 0xfb 0x48 0x56 0x8d 0x8c 0x4e 0x1c 0x2c 0x53 0x41 0xe 0xca [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:358 USIM-API - ik(f4) :0x9a 0x37 0x68 0x4a 0xfb 0xd4 0x60 0xd7 0xea 0xc8 0x51 0x88 0xba 0xa9 0x9f 0x6d [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:360 USIM-API - ak(f5) : 24A2B6D14BA5 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:371 USIM-API - Retrieved SQN 000000000000 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/API/USIM/usim_api.c:393 USIM-API - Comparing the XMAC with the MAC included in AUTN Succeeded [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:274 EMM-PROC - Timer T3416 (-1) expires in 30 seconds [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:465 EMM_AS_NO_KEY_AVAILABLE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_SECURITY_RES (203) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1284 EMMAS-SAP - Send AS security response [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:772 EMMAS-SAP - Send Authentication Response message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:928 EMM-PROC _authentication_kasme INPUT CK 0xa0 0x23 0x38 0xa7 0xfb 0x48 0x56 0x8d 0x8c 0x4e 0x1c 0x2c 0x53 0x41 0xe 0xca [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:930 EMM-PROC _authentication_kasme INPUT IK 0x9a 0x37 0x68 0x4a 0xfb 0xd4 0x60 0xd7 0xea 0xc8 0x51 0x88 0xba 0xa9 0x9f 0x6d [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:932 EMM-PROC _authentication_kasme INPUT AUTN 0x24 0xa2 0xb6 0xd1 0x4b 0xa5 0x80 0x0 0x33 0x95 0x67 0x64 0xaf 0x90 0x3 0x50 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:934 EMM-PROC _authentication_kasme INPUT KASME LENGTH 32 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:964 EMM-PROC _authentication_kasme P0 MCC,MNC 00 F1 10 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:986 EMM-PROC _authentication_kasme input S to KFD (length 14)10 00 F1 10 00 03 24 A2 B6 D1 4B A5 00 06 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:998 EMM-PROC KASME (l=32)0x9b 0x42 0x62 0x30 0x5f 0x20 0x31 0xa1 0xa9 0x5 0xec 0xfc 0xde 0x92 0xbf 0x9c 0xfd 0xc0 0x24 0x9e 0xeb 0x65 0x6b 0x94 0xa 0xb0 0xa4 0x44 0xa4 0x49 0x38 0x32 [NAS][I][UE] Received 1 events [PDCP][I][FRAME 00000][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 1, muiP 8, confirmP 0, mode 1 [RLC][I][FRAME 00000][ UE][MOD 01][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 19 Bytes, NB SDU 2 current_sdu_index=1 next_sdu_index=2 conf 0 mui 8 vtA 3 vtS 3 [RRC][N][eNB 0] Frame 42: received a DCCH 1 message on SRB 1 with Size 14 from UE 13bd [RRC][I][FRAME 00042][eNB][MOD 00][RNTI 13bd] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I]Successfully sent 59 bytes on stream 1 for assoc_id 1 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 39 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_DownlinkNASTransportIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3150) [RRC][I][eNB 0] Received S1AP_DOWNLINK_NAS: ue_initial_id 2, eNB_ue_s1ap_id 3009731 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 3, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 21 Bytes, NB SDU 2 current_sdu_index=1 next_sdu_index=2 conf 0 mui 3 vtA 1 vtS 1 [RRC][N][UE 1] Frame 42: received a DCCH 1 message on SRB 1 with Size 16 from eNB 0 [NAS][I][UE 1] Received NAS_DOWNLINK_DATA_IND: UEid 1, length 13 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_DATA_IND (211) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:412 EMMAS-SAP - Received AS data transfer indication (ueid=1, delivered=TRUE, length=13) [NAS][W] /root/openairinterface5g/openair3/NAS/COMMON/API/NETWORK/nas_message.c:328 MAC failure but continue due to EIA0 selected [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:312 EMMAS-SAP - Received EMM message (length=7) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/emm_msg.c:117 EMM-MSG - Message Type 0x5d [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:469 EMMAS-SAP - Received Security Mode Command message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:475 Execute the security mode control procedure initiated by the network: imeisvrequest 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:153 EMM-PROC - Security mode control requested (ksi=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Authentication.c:463 EMM-PROC - Delete authentication data RAND and RES [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:187 EMM-PROC - Update the non-current EPS security context seea=0 seia=2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:203 EMM-PROC - Update the non-current EPS security context knas_enc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:418 _security_knas_enc with algo dist 1 algo id 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:217 EMM-PROC - Update the non-current EPS security context knas_int [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:444 _security_knas_int with algo dist 2 algo id 2 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:231 EMM-PROC - Update the non-current EPS security context kenb [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:476 _security_kenb with count= 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:243 EMM-PROC - NAS security mode command accepted by the UE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SecurityModeControl.c:259 EMM-PROC - Update Current security context [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:434 EPS security context exists is new 1 KSI 0 SQN 0 count 0 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:436 knas_int 0x6f 0x18 0xa 0x40 0x18 0xcd 0x15 0x97 0x9 0xe2 0xf8 0x7 0xac 0xb8 0x35 0x40 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:438 knas_enc 0x90 0xe5 0xa0 0xc9 0x9d 0xc1 0x22 0x57 0xc9 0x72 0xbd 0xdf 0x17 0x35 0x31 0x48 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:440 kasme 0x9b 0x42 0x62 0x30 0x5f 0x20 0x31 0xa1 0xa9 0x5 0xec 0xfc 0xde 0x92 0xbf 0x9c 0xfd 0xc0 0x24 0x9e 0xeb 0x65 0x6b 0x94 0xa 0xb0 0xa4 0x44 0xa4 0x49 0x38 0x32 [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:461 EPS security context exists knas_enc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_SECURITY_RES (203) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1284 EMMAS-SAP - Send AS security response [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:853 EMMAS-SAP - Send Security Mode Complete message [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/SecurityModeComplete.c:79 SECURITY MODE COMMAND COMPLETE: presencemask: 0 [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/SecurityModeComplete.c:93 SECURITY MODE COMMAND COMPLETE done !!! Byte length: 11, Zero bits: 0 m: 000000000000000000075e Key:6f180a4018cd159709e2f807acb83540 Message:00075e out: 4587d3e0cc39d6fd5bbdbb93f2c0fcdb [NAS][I][UE] Received 1 events [PDCP][I][FRAME 00000][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 1, muiP 9, confirmP 0, mode 1 [RLC][I][FRAME 00000][ UE][MOD 01][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 16 Bytes, NB SDU 3 current_sdu_index=2 next_sdu_index=3 conf 0 mui 9 vtA 4 vtS 4 [RRC][N][eNB 0] Frame 45: received a DCCH 1 message on SRB 1 with Size 11 from UE 13bd [RRC][I][FRAME 00045][eNB][MOD 00][RNTI 13bd] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I]Successfully sent 56 bytes on stream 1 for assoc_id 1 [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 200 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_InitialContextSetupRequestIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:1003) [S1AP][I]Received NAS message with the E_RAB setup procedure [RRC][I][eNB 0] Received S1AP_INITIAL_CONTEXT_SETUP_REQ: ue_initial_id 2, eNB_ue_s1ap_id 3009731, nb_of_e_rabs 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 13bd] rrc_eNB_process_GTPV1U_CREATE_TUNNEL_RESP tunnel (2034233417, 2034233417) bearer UE context index 0, msg index 0, id 5, gtp addr len 4 [RRC][I][eNB 0][UE 13bd] Selected security algorithms (0x7fefea0915dc): 0, 2, changed [RRC][I][eNB 0][UE 13bd] Saved security key 701D7711B077F9E6B3952446C01D2F697A2053F25B16E50FCAA273AF558DDAB9 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 13bd] Logical Channel DL-DCCH, Generate SecurityModeCommand (bytes 3) [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 3, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 8 Bytes, NB SDU 3 current_sdu_index=2 next_sdu_index=3 conf 0 mui 3 vtA 2 vtS 2 [RRC][N][UE 1] Frame 46: received a DCCH 1 message on SRB 1 with Size 3 from eNB 0 [RRC][I][UE 1] Received securityModeCommand (eNB 0) [RRC][I][UE 1] Frame 46: Receiving from SRB1 (DL-DCCH), Processing securityModeCommand (eNB 0) [RRC][I][UE 1] Security algorithm is set to eea0 [RRC][I][UE 1] Integrity protection algorithm is set to eia2 [RRC][I][UE 1] Frame 46: Receiving from SRB1 (DL-DCCH), encoding securityModeComplete (eNB 0) [PDCP][I][FRAME 00046][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 1, muiP 10, confirmP 0, mode 1 [RLC][I][FRAME 00046][ UE][MOD 01][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 7 Bytes, NB SDU 4 current_sdu_index=3 next_sdu_index=4 conf 0 mui 10 vtA 5 vtS 5 [OSA][E]Mismatch found in integrity for algorithm 2, got 8d.37.8f.a7, expecting 8b.2b.24.d0 [PDCP][E][OSA][RB 1] eNB failed to validate MAC-I of incoming PDU [RRC][N][eNB 0] Frame 48: received a DCCH 1 message on SRB 1 with Size 2 from UE 13bd [RRC][I][FRAME 00048][eNB][MOD 00][RNTI 13bd] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00048][eNB][MOD 00][RNTI 13bd] received securityModeComplete on UL-DCCH 1 from UE [RRC][I][FRAME 00048][eNB][MOD 00][RNTI 13bd] Logical Channel DL-DCCH, Generate UECapabilityEnquiry (bytes 3) [PDCP][I][FRAME 00048][eNB][MOD 00][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 4, confirmP 0, mode 1 [RLC][I][FRAME 00048][eNB][MOD 00][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 8 Bytes, NB SDU 4 current_sdu_index=3 next_sdu_index=4 conf 0 mui 4 vtA 3 vtS 3 [OSA][E]Mismatch found in integrity for algorithm 2, got 4d.21.ca.d3, expecting 04.22.b1.10 [PDCP][E][OSA][RB 1] UE failed to validate MAC-I of incoming PDU [RRC][N][UE 1] Frame 49: received a DCCH 1 message on SRB 1 with Size 3 from eNB 0 [RRC][I][UE 1] Received Capability Enquiry (eNB 0) [RRC][I][UE 1] Frame 49: Receiving from SRB1 (DL-DCCH), Processing UECapabilityEnquiry (eNB 0) [PDCP][I][FRAME 00049][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 1, muiP 11, confirmP 0, mode 1 [RLC][I][FRAME 00049][ UE][MOD 01][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 24 Bytes, NB SDU 5 current_sdu_index=4 next_sdu_index=5 conf 0 mui 11 vtA 6 vtS 6 [OSA][E]Mismatch found in integrity for algorithm 2, got e6.88.16.36, expecting d5.cd.9b.97 [PDCP][E][OSA][RB 1] eNB failed to validate MAC-I of incoming PDU [RRC][N][eNB 0] Frame 51: received a DCCH 1 message on SRB 1 with Size 19 from UE 13bd [RRC][I][FRAME 00051][eNB][MOD 00][RNTI 13bd] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00051][eNB][MOD 00][RNTI 13bd] received ueCapabilityInformation on UL-DCCH 1 from UE [RRC][I]got UE capabilities for UE 13bd [RRC][I]RRCConnectionReconfiguration Encoded 1112 bits (139 bytes) [RRC][I][eNB 0] Frame 51, Logical Channel DL-DCCH, Generate RRCConnectionReconfiguration (bytes 139, UE id 13bd) [SCTP][I]Successfully sent 46 bytes on stream 1 for assoc_id 1 [PDCP][I][FRAME 00051][eNB][MOD 00][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 5, confirmP 0, mode 1 [RLC][I][FRAME 00051][eNB][MOD 00][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 144 Bytes, NB SDU 5 current_sdu_index=4 next_sdu_index=5 conf 0 mui 5 vtA 4 vtS 4 [OSA][E]Mismatch found in integrity for algorithm 2, got 02.ac.a3.0a, expecting a6.ff.ee.21 [PDCP][E][OSA][RB 1] UE failed to validate MAC-I of incoming PDU [RRC][N][UE 1] Frame 51: received a DCCH 1 message on SRB 1 with Size 139 from eNB 0 [RRC][I][UE 1] Frame 51: Receiving from SRB1 (DL-DCCH), Processing RRCConnectionReconfiguration (eNB 0) [RRC][I]Radio Resource Configuration is present [RRC][I]Save physicalConfigDedicated if present [RRC][I]Update pdsch_ConfigDedicated config [RRC][I]Update pusch_ConfigDedicated config [RRC][I]Update pucch_ConfigDedicated config [RRC][I]Update cqi_ReportConfig config (size=48,48) [RRC][I]Update cqi_ReportPeriodic config (size=152,152) [RRC][I]Update schedulingRequestConfig config [RRC][I]Keep old config for soundingRS_UL_ConfigDedicated [RRC][I]Update antennaInfo config [PHY][I]New Transmission Mode 1 [PHY][I]Configured Transmission Mode 1 [RRC][I]Update uplinkPowerControlDedicated config [RRC][I]Update tpc_PDCCH_ConfigPUCCH config [RRC][I]Update tpc_PDCCH_ConfigPUSCH config [PDCP][N][FRAME 00051][ UE][MOD 01][RNTI 13bd][SRB 02] Action ADD LCID 2 (SRB id 2) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00051][ UE][MOD 01][RNTI 13bd] [SRB 2] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00051][ UE][MOD 01][RNTI 13bd][SRB AM 02][CONFIGURE] max_retx_threshold 32 poll_pdu 8 poll_byte 16960 t_poll_retransmit 15 t_reordering 35 t_status_prohibit 10 [RRC][I][UE 1], CONFIG_SRB2 2 corresponding to eNB_index 0 [RRC][I]Applying Explicit SRB2 logicalChannelConfig [RRC][I][FRAME 00051][RRC_UE][MOD 01][][--- MAC_CONFIG_REQ (SRB2 eNB 0) --->][MAC_UE][MOD 01][] [MAC][I][CONFIG][UE 1] Configuring MAC/PHY from eNB 0 [MAC][I][CONFIG][UE 1] Applying RRC logicalChannelConfig from eNB0 [MAC][I][CONFIG][UE1] Applying RRC macMainConfig from eNB0 [PHY][I]Transmission Mode 2 [PHY][I]Disable SIB MIB decoding [PHY][I]C-RNTI 13bd 13bd [RRC][I][UE 1] default DRB = 1 [PDCP][N][FRAME 00051][ UE][MOD 01][RNTI 13bd][DRB 01] Action ADD LCID 3 (DRB id 1) configured with SN size 12 bits and RLC AM [RLC][I][FRAME 00051][ UE][MOD 01][RNTI 13bd] [DRB 1] rrc_rlc_add_rlc DRB [RLC][I][FRAME 00051][ UE][MOD 01][RNTI 13bd][DRB AM 01][CONFIGURE] max_retx_threshold 8 poll_pdu 16 poll_byte 65535 t_poll_retransmit 50 t_reordering 35 t_status_prohibit 25 [RRC][I][UE 1] Frame 51: processing RRCConnectionReconfiguration: reconfiguring DRB 1/LCID 3 [RRC][I][FRAME 00051][RRC_UE][MOD 01][][--- MAC_CONFIG_REQ (DRB 1 eNB 0) --->][MAC_UE][MOD 01][] [MAC][I][CONFIG][UE 1] Configuring MAC/PHY from eNB 0 [MAC][I][CONFIG][UE 1] Applying RRC logicalChannelConfig from eNB0 [MAC][I][CONFIG][UE1] Applying RRC macMainConfig from eNB0 [PHY][I]Transmission Mode 2 [PHY][I]Disable SIB MIB decoding [PHY][I]C-RNTI 13bd 13bd [RRC][I][UE 1] State = RRC_CONNECTED (eNB 0) [RRC][I][FRAME 00051][ UE][MOD 01][RNTI 13bd] Logical Channel UL-DCCH (SRB1), Generating RRCConnectionReconfigurationComplete (bytes 2, eNB_index 0) [RRC][I][UE 1] State = RRC_RECONFIGURED (eNB 0) [NAS][I][UE 1] Received NAS_CONN_ESTABLI_CNF: errCode 1, length 95 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_ESTABLISH_CNF (206) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:488 EMMAS-SAP - Received AS connection establish confirm Byte length: 98, Zero bits: 0 m: 00000001040000000107420149062000f1100001003a5201c101090a036c7465026d64026a7005011900000327228080211002000010810608080808830608080404000d0408080808000d0408080404500bf600f110000201d2000b725949640101 Key:6f180a4018cd159709e2f807acb83540 Message:0107420149062000f1100001003a5201c101090a036c7465026d64026a7005011900000327228080211002000010810608080808830608080404000d0408080808000d0408080404500bf600f110000201d2000b725949640101 out: 1bae042fcb7a5f80855069a67bc192ca [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/emm_msg.c:117 EMM-MSG - Message Type 0x42 [NAS][W] /root/openairinterface5g/openair3/NAS/COMMON/EMM/MSG/AttachAccept.c:197 DECODED 87 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_recv.c:135 EMMAS-SAP - Received Attach Accept message [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:352 EMM-PROC - EPS attach accepted by the network [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/Attach.c:355 EMM-PROC - Stop timer T3410 (-1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_sap.c:155 ESM-SAP - Received primitive ESM_DEFAULT_EPS_BEARER_CONTEXT_ACTIVATE_REQ (1) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_recv.c:290 ESM-SAP - Received Activate Default EPS Bearer Context Request message (pti=1, ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:372 ESM-PROC - PDN connectivity accepted by the network (pti=1) APN = 03"ltemdjp", IP address = 25.0.0.3 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_pt.c:383 ESM-FSM - Status of procedure transaction 1 changed: PROCEDURE TRANSACTION PENDING ===> PROCEDURE TRANSACTION INACTIVE [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/PdnConnectivity.c:774 ESM-PROC - Update PDN connection (pid=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/DefaultEpsBearerContextActivation.c:103 ESM-PROC - Default EPS bearer context activation requested by the network (ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr.c:219 ESM-FSM - EPS bearer context 5 assigned [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr_context.c:118 ESM-PROC - Create new default EPS bearer context (ebi=5) for PDN connection (pid=0) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr_context.c:288 ESM-PROC - executing ifconfig oip2 25.0.0.3 netmask 255.0.0.0 broadcast 25.255.255.255 up && ip rule add from 25.0.0.3/32 table 202 && ip rule add to 25.0.0.3/32 table 202 && ip route add default dev oip2 table 202 [PDCP][I][FRAME 00051][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 1, muiP 12, confirmP 0, mode 1 [RLC][I][FRAME 00051][ UE][MOD 01][RNTI 13bd][SRB AM 01] RLC_AM_DATA_REQ size 7 Bytes, NB SDU 6 current_sdu_index=5 next_sdu_index=6 conf 0 mui 12 vtA 7 vtS 7 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/SAP/esm_send.c:290 ESM-SAP - Send Activate Default EPS Bearer Context Accept message (pti=0, ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/COMMON/ESM/MSG/esm_msg.c:269 ESM-MSG - Encoded ESM message header (3) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/DefaultEpsBearerContextActivation.c:188 ESM-PROC - Default EPS bearer context activation accepted by the UE (ebi=5) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/ESM/esm_ebr.c:321 ESM-FSM - Status of EPS bearer context 5 changed: BEARER CONTEXT INACTIVE ===> BEARER CONTEXT ACTIVE [NAS][E] /root/openairinterface5g/openair3/NAS/UE/API/USER/user_api.c:308 USR-API - send() failed, Destination address required [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:434 EPS security context exists is new 0 KSI 0 SQN 1 count 16777216 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:436 knas_int 0x6f 0x18 0xa 0x40 0x18 0xcd 0x15 0x97 0x9 0xe2 0xf8 0x7 0xac 0xb8 0x35 0x40 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:438 knas_enc 0x90 0xe5 0xa0 0xc9 0x9d 0xc1 0x22 0x57 0xc9 0x72 0xbd 0xdf 0x17 0x35 0x31 0x48 [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:440 kasme 0x9b 0x42 0x62 0x30 0x5f 0x20 0x31 0xa1 0xa9 0x5 0xec 0xfc 0xde 0x92 0xbf 0x9c 0xfd 0xc0 0x24 0x9e 0xeb 0x65 0x6b 0x94 0xa 0xb0 0xa4 0x44 0xa4 0x49 0x38 0x32 [NAS][W] /root/openairinterface5g/openair3/NAS/UE/EMM/LowerLayer.c:461 EPS security context exists knas_enc [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:198 EMMAS-SAP - Received primitive EMMAS_DATA_REQ (210) [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_as.c:1075 EMMAS-SAP - Send AS data transfer request [NAS][I] /root/openairinterface5g/openair3/NAS/UE/EMM/SAP/emm_send.c:329 EMMAS-SAP - Send Attach Complete message Byte length: 16, Zero bits: 0 m: 000000010000000001074300035200c2 Key:6f180a4018cd159709e2f807acb83540 Message:01074300035200c2 out: 7c4e401e10e7666ca986306f66e58d4c [NAS][I][UE] Received 1 events [PDCP][I][FRAME 00000][ UE][MOD 01][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_UE: instance 2, rb_id 2, muiP 13, confirmP 0, mode 1 [RLC][I][FRAME 00000][ UE][MOD 01][RNTI 13bd][SRB AM 02] RLC_AM_DATA_REQ size 21 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 13 vtA 0 vtS 0 [OSA][E]Mismatch found in integrity for algorithm 2, got e0.1d.ab.3e, expecting 15.b9.6c.cc [PDCP][E][OSA][RB 1] eNB failed to validate MAC-I of incoming PDU [RRC][N][eNB 0] Frame 54: received a DCCH 1 message on SRB 1 with Size 2 from UE 13bd [RRC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd] UE State = RRC_RECONFIGURED (default DRB, xid 2) [PDCP][N][FRAME 00054][eNB][MOD 00][RNTI 13bd][SRB 02] Action ADD LCID 2 (SRB id 2) configured with SN size 5 bits and RLC AM [PDCP][N][FRAME 00054][eNB][MOD 00][RNTI 13bd][DRB 01] Action ADD LCID 3 (DRB id 1) configured with SN size 12 bits and RLC AM [RLC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd] [SRB 2] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd][SRB AM 02][CONFIGURE] max_retx_threshold 32 poll_pdu 8 poll_byte 16960 t_poll_retransmit 15 t_reordering 35 t_status_prohibit 10 [RLC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd] [DRB 1] rrc_rlc_add_rlc DRB [RLC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd][DRB AM 01][CONFIGURE] max_retx_threshold 8 poll_pdu 16 poll_byte 65535 t_poll_retransmit 50 t_reordering 35 t_status_prohibit 25 [RRC][I][eNB 0] Frame 54 CC 0 : SRB2 is now active [RRC][I][eNB 0] Frame 54 : Logical Channel UL-DCCH, Received RRCConnectionReconfigurationComplete from UE rnti 13bd, reconfiguring DRB 1/LCID 3 [RRC][I][eNB 0] Frame 54 : Logical Channel UL-DCCH, Received RRCConnectionReconfigurationComplete from UE 0, reconfiguring DRB 1/LCID 3 [MAC][I][CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (13bd) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7fef68004470 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 2 [S1AP][I]initial_ctxt_resp_p: e_rab ID 5, enb_addr 10.20.0.131, SIZE 4 [SCTP][I]Successfully sent 40 bytes on stream 1 for assoc_id 1 [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7fef68004470 for UE 0 [RRC][N][eNB 0] Frame 54: received a DCCH 2 message on SRB 2 with Size 16 from UE 13bd [MAC][I][eNB 0], Frame 55, DCCH1->DLSCH, CC_id 0, Requesting 97 bytes from RLC (RRC message) [RRC][I][FRAME 00054][eNB][MOD 00][RNTI 13bd] Received on DCCH 2 RRC_DCCH_DATA_IND [SCTP][I]Successfully sent 61 bytes on stream 1 for assoc_id 1 [MAC][I][eNB 0], Frame 56, DCCH1->DLSCH, CC_id 0, Requesting 97 bytes from RLC (RRC message) [SCTP][I]Found data for descriptor 51 [SCTP][I]Received notification for sd 51, type 32777 [SCTP][I]Found data for descriptor 51 [SCTP][I][1][51] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I]Decoding message S1ap_DownlinkNASTransportIEs (/root/openairinterface5g/cmake_targets/oaisim_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3150) [RRC][I][eNB 0] Received S1AP_DOWNLINK_NAS: ue_initial_id 0, eNB_ue_s1ap_id 3009731 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 13bd]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 2, muiP 6, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 13bd][SRB AM 02] RLC_AM_DATA_REQ size 44 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 6 vtA 0 vtS 0 [MAC][I][eNB 0], Frame 57, DCCH1->DLSCH, CC_id 0, Requesting 97 bytes from RLC (RRC message) [OSA][E]Mismatch found in integrity for algorithm 2, got cf.b8.2f.6e, expecting 00.00.00.00 [PDCP][E][OSA][RB 2] UE failed to validate MAC-I of incoming PDU [RRC][N][UE 1] Frame 57: received a DCCH 2 message on SRB 2 with Size 39 from eNB 0 [RRC][E][UE 1] Frame 57: Received message on DL-DCCH (SRB2), should not have ... [MAC][I][eNB 0], Frame 58, DCCH1->DLSCH, CC_id 0, Requesting 97 bytes from RLC (RRC message) [MAC][I][eNB 0], Frame 59, DCCH1->DLSCH, CC_id 0, Requesting 97 bytes from RLC (RRC message) [MAC][E]scheduled retransmission in forbidden RBs [MAC][E]scheduled retransmission in forbidden RBs [PHY][I]bad NPRB = 0 bad DCI 1A !!! [PHY][E][UE 1] Frame 799, subframe 4: Problem in DCI! [MAC][E]scheduled retransmission in forbidden RBs [MAC][E]scheduled retransmission in forbidden RBs [PHY][I]UE 0 : rnti 13bd [PHY][I]UE 1 : rnti 1d0d [MAC][I]UE rnti 13bd : in synch, PHR -9 dB CQI 12 [MAC][I]UE rnti 1d0d : in synch, PHR -12 dB CQI 12 [RRC][I]UE rnti 13bd failure timer 0/20000 [RRC][I]UE rnti 1d0d failure timer 0/20000 [MAC][E]scheduled retransmission in forbidden RBs