up@UP-APL01:~/openairinterface5g$ sudo ./targets/bin/lte-softmodem.Rel14 -O targets/PROJECTS/GENERIC-LTE-EPC/CONF/rcc_LMSSDR_config.conf --rf-config-file ./targets/ARCH/LMSSDR/LimeSDR_above_1p8GHz_1v4.ini # /dev/cpu_dma_latency set to 0us log init done num component carrier 1 WARNING: setting 'gtpu_log_level' not found in configuration file WARNING: setting 'gtpu_log_verbosity' not found in configuration file WARNING: setting 'udp_log_level' not found in configuration file WARNING: setting 'udp_log_verbosity' not found in configuration file WARNING: setting 'osa_log_level' not found in configuration file WARNING: setting 'osa_log_verbosity' not found in configuration file ---------------------------------------------------------------------- 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: 208: MNC: 95: 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: 2652500000: 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: 1: nb_antennas_tx for CC 0: 1: nb_antennas_rx for CC 0: 1: rach_numberOfRA_Preambles for CC 0: 15: rach_preamblesGroupAConfig for CC 0: 0: rach_powerRampingStep for CC 0: 2: rach_preambleInitialReceivedTargetPower for CC 0: 8: 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: -30: 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: 1: 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: -96: pucch_p0_Nominal for CC 0: -100: 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: 0: Global log level: info HW log level: info PHY log level: info MAC log level: info RLC log level: info PDCP log level: info RRC log level: info UDP log level: info GTP log level: info OSA log level: info -------------------------------------------------------- Downlink frequency/ uplink offset of CC_id 0 set to 2652500000/-120000000 configuring for eNB CPU Freq is 1.094483 reported resolution = 1 ns [HW][I]Version: Branch: master Abrev. Hash: ae0494b Date: Fri Nov 17 15:59:21 2017 +0100 [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] = 0x7f9e0e237010 (286720 bytes) [openair][LTE_PHY][INIT] common_vars->txdataF[0][5] = 0x7f9e0e1f0010 (286720 bytes) [openair][LTE_PHY][INIT] common_vars->txdata[0][0] = 0x7f9e0e1a4010 (307200 bytes) [openair][LTE_PHY][INIT] common_vars->rxdata[0][0] = 0x7f9e0e158010 (307200 bytes) [openair][LTE_PHY][INIT] common_vars->rxdata_7_5kHz[0][0] = 0x160eb7e0 (61440 bytes) [openair][LTE_PHY][INIT] prach_vars->rxsigF[0] = 0x16495ec0 [openair][LTE_PHY][INIT] prach_vars->prach_ifft[0] = 0x1649bed0 [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 16 number of enb max 1 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 CPU Freq is 1.094471 frame_parms->N_RB_DL=25 frame_parms->N_RB_UL=25 frame_parms->Nid_cell=0 frame_parms->Ncp=0 frame_parms->Ncp_UL=0 frame_parms->nushift=0 frame_parms->frame_type=0 frame_parms->tdd_config=3 frame_parms->tdd_config_S=0 frame_parms->mode1_flag=1 frame_parms->nb_antenna_ports_eNB=1 frame_parms->nb_antennas_tx=1 frame_parms->nb_antennas_rx=1 frame_parms->ofdm_symbol_size=512 frame_parms->nb_prefix_samples=36 frame_parms->nb_prefix_samples0=40 frame_parms->first_carrier_offset=362 frame_parms->samples_per_tti=7680 frame_parms->symbols_per_tti=14 HW: Configuring card 0, nb_antennas_tx/rx 1/1 Card 0, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 0, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 0, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 0, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 1, nb_antennas_tx/rx 1/1 Card 1, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 1, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 1, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 1, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 2, nb_antennas_tx/rx 1/1 Card 2, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 2, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 2, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 2, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 3, nb_antennas_tx/rx 1/1 Card 3, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 3, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 3, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 3, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 4, nb_antennas_tx/rx 1/1 Card 4, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 4, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 4, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 4, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 5, nb_antennas_tx/rx 1/1 Card 5, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 5, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 5, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 5, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 6, nb_antennas_tx/rx 1/1 Card 6, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 6, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 6, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 6, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 HW: Configuring card 7, nb_antennas_tx/rx 1/1 Card 7, channel 0, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 2652500000.000000, rx_freq 2532500000.000000 Card 7, channel 1, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 7, channel 2, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 Card 7, channel 3, Setting tx_gain 100.000000, rx_gain 120.000000, tx_freq 0.000000, rx_freq 0.000000 [HW][I]CPU Affinity of main() function is... CPU_0 CPU_1 [PHY][I]Intializing L2 [MAC][I][l2_init] [MAIN] MAC_INIT_GLOBAL_PARAM IN... [MAC][I][mac_init_global_param] [MAIN] CALLING RLC_MODULE_INIT... [MAC][I][mac_init_global_param] [MAIN] RLC_MODULE_INIT OK, malloc16 for mac_rlc_xface... [MAC][I][mac_init_global_param] [MAIN] malloc16 OK, mac_rlc_xface @ 0x1812c890 [MAC][I][mac_init_global_param] [MAIN] RLC interface setup and init [PDCP][I]PDCP layer has been initialized [MAC][I][mac_init_global_param] [MAIN] Init Global Param Done [MAC][I][l2_init] [MAIN] init eNB MAC functions [MAC][I][l2_init] [MAIN] init UE MAC functions [MAC][I][l2_init] [MAIN] PHY Frame configuration [MAC][I][mac_top_init] [MAIN] Init function start:Nb_UE_INST=0 [MAC][I][mac_top_init] [MAIN] Init function start:Nb_eNB_INST=1 [MAC][I][mac_top_init] [MAIN] calling RRC [RRC][I][eNB] handover active state is 0 [RRC][I][eNB] eMBMS active state is 0 [MAC][I][mac_top_init] [MAIN][INIT] Init function finished [SCTP][I][sctp_eNB_task] Starting SCTP layer [S1AP][I][s1ap_eNB_task] Starting S1AP layer [UDP][I]Initializing UDP task interface [UDP][I]Initializing UDP task interface: DONE [GTPV1U][I]Initializing GTPU stack 0x1033f00 ITTI tasks created Wait for the ITTI initialize message [UDP][I]Initializing UDP for local address 192.168.0.70 with port 2152 [UDP][I]Inserting new descriptor for task 11, sd 40 [UDP][I]Initializing UDP for local address 192.168.0.70 with port 2152: DONE [ENB_APP][I][eNB_app_register] [eNB 0] eNB_app_register for instance 0 [S1AP][I][s1ap_eNB_handle_register_eNB] Registered new eNB[0] and macro eNB id 3584 [S1AP][I][s1ap_eNB_register_mme] [eNB 0] check the mme registration state [RRC][I][eNB 0] Received RRC_CONFIGURATION_REQ [SCTP][I][sctp_handle_new_association_req] sctp_bindx SCTP_BINDX_ADD_ADDR socket bound to : 192.168.0.70 [SCTP][I][sctp_handle_new_association_req] Converted ipv4 address 192.168.0.80 to network type [SCTP][I][sctp_handle_new_association_req] connectx assoc_id 18 in progress..., used 1 addresses [SCTP][I][sctp_handle_new_association_req] Inserted new descriptor for sd 41 in list, nb elements 1, assoc_id 18 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 0] Init... [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][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY [MAC][I][rrc_mac_config_req] [CONFIG]SIB2/3 Contents (partial) [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.n_SB = 1 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.hoppingMode = 0 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.pusch_HoppingOffset = 0 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.enable64QAM = 0 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.groupHoppingEnabled = 1 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.groupAssignmentPUSCH = 0 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.sequenceHoppingEnabled = 0 [MAC][I][rrc_mac_config_req] [CONFIG]pusch_config_common.cyclicShift = 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 0] OPENAIR RRC IN.... [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32769 [SCTP][I][sctp_eNB_read_from_socket] Client association changed: 0 [SCTP][I][sctp_get_peeraddresses] ---------------------- [SCTP][I][sctp_get_peeraddresses] Peer addresses: [SCTP][I][sctp_get_peeraddresses] - [192.168.0.80] [SCTP][I][sctp_get_peeraddresses] ---------------------- [SCTP][I][sctp_get_sockinfo] ---------------------- [SCTP][I][sctp_get_sockinfo] SCTP Status: [SCTP][I][sctp_get_sockinfo] assoc id .....: 18 [SCTP][I][sctp_get_sockinfo] state ........: 4 [SCTP][I][sctp_get_sockinfo] instrms ......: 2 [SCTP][I][sctp_get_sockinfo] outstrms .....: 2 [SCTP][I][sctp_get_sockinfo] fragmentation : 1452 [SCTP][I][sctp_get_sockinfo] pending data .: 0 [SCTP][I][sctp_get_sockinfo] unack data ...: 0 [SCTP][I][sctp_get_sockinfo] rwnd .........: 106496 [SCTP][I][sctp_get_sockinfo] peer info : [SCTP][I][sctp_get_sockinfo] state ....: 2 [SCTP][I][sctp_get_sockinfo] cwnd .....: 4380 [SCTP][I][sctp_get_sockinfo] srtt .....: 0 [SCTP][I][sctp_get_sockinfo] rto ......: 3000 [SCTP][I][sctp_get_sockinfo] mtu ......: 1500 [SCTP][I][sctp_get_sockinfo] ---------------------- [SCTP][I][sctp_eNB_read_from_socket] Comm up notified for sd 41, assigned assoc_id 18 [S1AP][I][s1ap_eNB_generate_s1_setup_request] 3584 -> 00e000 [SCTP][I][sctp_send_data] Successfully sent 59 bytes on stream 0 for assoc_id 18 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 27 received from port 36412, on stream 0, PPID 18 [S1AP][I][s1ap_decode_s1ap_s1setupresponseies] Decoding message S1ap_S1SetupResponseIEs (/home/up/openairinterface5g/cmake_targets/lte_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:3535) [S1AP][I][s1ap_eNB_handle_s1_setup_response] servedGUMMEIs.list.count 1 [S1AP][I][s1ap_eNB_handle_s1_setup_response] servedPLMNs.list.count 1 [ENB_APP][I][eNB_app_task] [eNB 0] Received S1AP_REGISTER_ENB_CNF: associated MME 1 Initializing eNB threads [PHY][I]Initializing eNB 0 CC_id 0 : (eNodeB_3GPP,synch_to_ext_device) LMSSDR: Initializing openair0_device for RRH ... cal 0: freq 3500000000.000000, offset 44.000000, diff 967500000.000000 cal 1: freq 2660000000.000000, offset 55.000000, diff 127500000.000000 cal 2: freq 2300000000.000000, offset 54.000000, diff 232500000.000000 cal 3: freq 1880000000.000000, offset 54.000000, diff 652500000.000000 cal 4: freq 816000000.000000, offset 79.000000, diff 1716500000.000000 [RRH] has loaded LMSSDR device. setup_eNB_buffers: frame_parms = 0x7f9e0e27e788 [PHY][I]Initializing eNB 0 CC_id 0 (eNodeB_3GPP,synch_to_ext_device), [HW][I][SCHED][eNB] eNB_thread_single started on CPU 0 TID 21674, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 waiting for sync (eNB_thread_single) Creating te_thread [PHY][I]thread te created id=21677[HW][I][SCHED][eNB] eNB_thread_prach started on CPU 1 TID 21678, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 [HW][I][SCHED][eNB] eNB_thread_synch started on CPU 0 TID 21679, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 waiting for sync (eNB_thread_synch) Setting eNB buffer to all-RX Sending sync to all threads got sync (eNB_thread_synch) got sync (eNB_thread_single) TYPE TO TERMINATE Entering ITTI signals handler Connecting to device: LimeSDR-USB, media=USB 3.0, module=FX3, addr=1d50:6108, serial=0009070105C6372A Reference clock 30.72 MHz Set sample rate 7.680000 MHz Set TX frequency 2652.500000 MHz RX LPF configured Filter calibrated. Filter order-4th, filter bandwidth set to 5 MHz.Real pole 1st order filter set to 2.5 MHz. Preemphasis filter not active TX LPF configured Rx calibration finished Tx calibration finished SR: 7.680 MHz SR: 7.680 MHz [PHY][I]rx_rf: rfdevice timing drift of 14960 samples (ts_off 7680) L [PHY][I]rx_rf: rfdevice timing drift of 5440 samples (ts_off 22640) [PHY][I]rx_rf: rfdevice timing drift of 10880 samples (ts_off 28080) [PHY][I][eNB 0][RAPROC] Frame 21 Terminating ra_proc for harq 3, UE 0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 21, Received CCCH: 55.9b.4b.47.c4.62, Terminating RA procedure for UE rnti 4179 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 21 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti 4179 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 21 Added user with rnti 4179 => UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 21 subfarme 5, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 4179] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 4179] Accept new connection from UE random UE identity (0x467cb4b459000000) MME code 0 TMSI 0 cause 1 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (4179) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd4003260 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 4179] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 4179]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI 4179][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 4179] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 21 subfarme 6, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd4003260 for UE 0 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 4179][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][schedule_ulsch_rnti] [eNB 0] frame 21 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 21 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 21 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 22, subframeP 0: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 4179) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 22 subframeP 0 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 22 subfarme 0, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 22 subfarme 1, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 22 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 22 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 22 subfarme 4, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 22, subframeP 5: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 4179 fsf 22/5, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 22, subframeP 5 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/4179] CC_id 0 Frame 22 subframeP 5 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 5) [MAC][I][SR_indication] [eNB 0][SR 4179] Frame 23 subframeP 0 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/4179] CC_id 0 Frame 23 subframeP 4 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 6) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 7/4179] CC_id 0 Frame 26 subframeP 7 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 7) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 7/4179] CC_id 0 Frame 29 subframeP 9 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 7) [RRC][I]Removing UE 4179 instance [RRC][W][eNB 0] Removing UE RNTI 4179 MAC: remove UE 0 rnti 4179 [MAC][I][rrc_mac_remove_ue] Removing UE 0 from Primary CC_id 0 (rnti 4179) [S1AP][W][s1ap_ue_context_release_req] Failed to find ue context associated with eNB ue s1ap id: 0 [S1AP][E][s1ap_eNB_task] Failed to find ue context associated with eNB ue s1ap id: 0 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 4179] Removed UE context [PHY][I][eNB 0][RAPROC] Frame 327 Terminating ra_proc for harq 4, UE 0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 327, Received CCCH: 52.f0.ac.e7.14.62, Terminating RA procedure for UE rnti 2544 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 327 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti 2544 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 327 Added user with rnti 2544 => UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 0, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 2544] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 2544] Accept new connection from UE random UE identity (0x4671ce0a2f000000) MME code 0 TMSI 0 cause 1 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (2544) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd4002d80 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 2544] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 2544]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI 2544][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 2544] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 1, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd4002d80 for UE 0 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 2544][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][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 4, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 328, subframeP 5: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 2544) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 328 subframeP 5 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 5, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 6, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 328 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 329, subframeP 0: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 2544 fsf 329/0, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 329, subframeP 0 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/2544] CC_id 0 Frame 329 subframeP 0 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 6) [MAC][I][SR_indication] [eNB 0][SR 2544] Frame 330 subframeP 0 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/2544] CC_id 0 Frame 330 subframeP 4 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/2544] CC_id 0 Frame 333 subframeP 6 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/2544] CC_id 0 Frame 336 subframeP 8 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [RRC][I]Removing UE 2544 instance [RRC][W][eNB 0] Removing UE RNTI 2544 MAC: remove UE 0 rnti 2544 [MAC][I][rrc_mac_remove_ue] Removing UE 0 from Primary CC_id 0 (rnti 2544) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 2544] Removed UE context [S1AP][W][s1ap_ue_context_release_req] Failed to find ue context associated with eNB ue s1ap id: 0 [S1AP][E][s1ap_eNB_task] Failed to find ue context associated with eNB ue s1ap id: 0 [PHY][I][eNB 0][RAPROC] Frame 629 Terminating ra_proc for harq 0, UE 0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 629, Received CCCH: 59.54.f8.b1.b.42, Terminating RA procedure for UE rnti 486b [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 629 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti 486b [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 629 Added user with rnti 486b => UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 0, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 486b] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 486b] Accept new connection from UE random UE identity (0xb4108b4f95000000) MME code 0 TMSI 0 cause 1 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (486b) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd4003650 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 486b] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 486b]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI 486b][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 486b] [SRB 1] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 486b][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][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 1, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd4003650 for UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 4, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 630, subframeP 5: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 486b) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 630 subframeP 5 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 5, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 6, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 630 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 631, subframeP 0: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 486b fsf 631/0, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 631, subframeP 0 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 2/486b] CC_id 0 Frame 631 subframeP 0 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 2) [MAC][I][SR_indication] [eNB 0][SR 486b] Frame 632 subframeP 0 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 0/486b] CC_id 0 Frame 632 subframeP 4 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 0) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 0/486b] CC_id 0 Frame 635 subframeP 6 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 0) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 0/486b] CC_id 0 Frame 638 subframeP 8 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 0) [RRC][I]Removing UE 486b instance [RRC][W][eNB 0] Removing UE RNTI 486b MAC: remove UE 0 rnti 486b [MAC][I][rrc_mac_remove_ue] Removing UE 0 from Primary CC_id 0 (rnti 486b) [S1AP][W][s1ap_ue_context_release_req] Failed to find ue context associated with eNB ue s1ap id: 0 [S1AP][E][s1ap_eNB_task] Failed to find ue context associated with eNB ue s1ap id: 0 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 486b] Removed UE context [PHY][I][eNB 0][RAPROC] Frame 939 Terminating ra_proc for harq 4, UE 0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 939, Received CCCH: 59.1b.e2.f7.46.b2, Terminating RA procedure for UE rnti 3bd0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 939 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti 3bd0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 939 Added user with rnti 3bd0 => UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 0, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0] Accept new connection from UE random UE identity (0x6b742fbe91000000) MME code 0 TMSI 0 cause 1 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (3bd0) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd4003650 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI 3bd0][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0] [SRB 1] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0][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][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 1, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd4003650 for UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 4, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 940, subframeP 5: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 3bd0) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 940 subframeP 5 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 5, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 6, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 940 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 941, subframeP 0: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 3bd0 fsf 941/0, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 941, subframeP 0 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/3bd0] CC_id 0 Frame 941 subframeP 0 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 6) [MAC][I][SR_indication] [eNB 0][SR 3bd0] Frame 942 subframeP 0 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/3bd0] CC_id 0 Frame 942 subframeP 4 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/3bd0] CC_id 0 Frame 945 subframeP 6 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/3bd0] CC_id 0 Frame 948 subframeP 8 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [RRC][I]Removing UE 3bd0 instance [RRC][W][eNB 0] Removing UE RNTI 3bd0 MAC: remove UE 0 rnti 3bd0 [MAC][I][rrc_mac_remove_ue] Removing UE 0 from Primary CC_id 0 (rnti 3bd0) [S1AP][W][s1ap_ue_context_release_req] Failed to find ue context associated with eNB ue s1ap id: 0 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 3bd0] Removed UE context [S1AP][E][s1ap_eNB_task] Failed to find ue context associated with eNB ue s1ap id: 0 [PHY][I][eNB 0][RAPROC] Frame 219 Terminating ra_proc for harq 4, UE 0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 219, Received CCCH: 57.8f.c2.cc.7e.e2, Terminating RA procedure for UE rnti a19 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 219 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti a19 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 219 Added user with rnti a19 => UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 0, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Accept new connection from UE random UE identity (0xeec72cfc78000000) MME code 0 TMSI 0 cause 1 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (a19) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd400a1c0 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI a19][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19] [SRB 1] rrc_rlc_add_rlc SRB [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 1, UE 0: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd400a1c0 for UE 0 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19][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][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 4, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 220, subframeP 5: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI a19) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 220 subframeP 5 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 5, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 6, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 220 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 221, subframeP 0: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti a19 fsf 221/0, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 221, subframeP 0 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/a19] CC_id 0 Frame 221 subframeP 0 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 6) [MAC][I][SR_indication] [eNB 0][SR a19] Frame 222 subframeP 0 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/a19] CC_id 0 Frame 222 subframeP 4 Scheduled UE 0 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 4) [MAC][I][rx_sdu] [eNB 0] CC_id 0 MAC CE_LCID 29 : ul_total_buffer = 91 (lcg increment 91) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/a19] CC_id 0 Frame 225 subframeP 6 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 5, rb_table_index 4, TBS 109, harq_pid 4) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/a19] CC_id 0 Frame 225 subframeP 7 Scheduled UE 0 (mcs 10, first rb 8, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/a19] CC_id 0 Frame 225 subframeP 8 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 6) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 7/a19] CC_id 0 Frame 225 subframeP 9 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 7) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 0/a19] CC_id 0 Frame 226 subframeP 0 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 0) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 1/a19] CC_id 0 Frame 226 subframeP 1 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 1) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 2/a19] CC_id 0 Frame 226 subframeP 2 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 2) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 3/a19] CC_id 0 Frame 226 subframeP 3 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 3) [RRC][N][eNB 0] Frame 226: received a DCCH 1 message on SRB 1 with Size 76 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] [RAPROC] Logical Channel UL-DCCH, processing RRCConnectionSetupComplete from UE (SRB1 Active) [S1AP][I][s1ap_eNB_handle_nas_first_req] Found usable eNB_ue_s1ap_id: 0x06692d 420141(10) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] UE State = RRC_CONNECTED [SCTP][I][sctp_send_data] Successfully sent 120 bytes on stream 1 for assoc_id 18 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I][s1ap_decode_s1ap_downlinknastransporties] Decoding message S1ap_DownlinkNASTransportIEs (/home/up/openairinterface5g/cmake_targets/lte_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 420141 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI a19]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 a19][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 [RRC][N][eNB 0] Frame 293: received a DCCH 1 message on SRB 1 with Size 14 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I][sctp_send_data] Successfully sent 59 bytes on stream 1 for assoc_id 18 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 41 received from port 36412, on stream 1, PPID 18 [S1AP][I][s1ap_decode_s1ap_downlinknastransporties] Decoding message S1ap_DownlinkNASTransportIEs (/home/up/openairinterface5g/cmake_targets/lte_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 420141 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI a19]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 a19][SRB AM 01] RLC_AM_DATA_REQ size 23 Bytes, NB SDU 2 current_sdu_index=1 next_sdu_index=2 conf 0 mui 0 vtA 2 vtS 2 [RRC][N][eNB 0] Frame 326: received a DCCH 1 message on SRB 1 with Size 11 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I][sctp_send_data] Successfully sent 56 bytes on stream 1 for assoc_id 18 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 198 received from port 36412, on stream 1, PPID 18 [S1AP][I][s1ap_decode_s1ap_initialcontextsetuprequesties] Decoding message S1ap_InitialContextSetupRequestIEs (/home/up/openairinterface5g/cmake_targets/lte_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:1003) [S1AP][I][s1ap_eNB_handle_initial_context_request] 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 420141, nb_of_e_rabs 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] rrc_eNB_process_GTPV1U_CREATE_TUNNEL_RESP tunnel (3396329693, 3396329693) bearer UE context index 0, msg index 0, id 5, gtp addr len 4 [RRC][I][eNB 0][UE a19] Selected security algorithms (0x7f9de40072c0): 0, 2, changed [RRC][I][eNB 0][UE a19] Saved security key 36E70E009F82E4F1D1B31A736D6C996417F9FA8EF145F994093887963AEB437A KeNB:36e70e009f82e4f1d1b31a736d6c996417f9fa8ef145f994093887963aeb437a KRRCenc:4db9c727715d91dedfbe21ff8e3eaf8b8270c61815844519dcc0915d56a8a070 KRRCint:e26a9ddb2a6f98e640fe691991d8695c1160d926f191b1db2f4e13e488af24f5 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Logical Channel DL-DCCH, Generate SecurityModeCommand (bytes 3) [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI a19]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 a19][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 2 vtS 3 [RRC][N][eNB 0] Frame 374: received a DCCH 1 message on SRB 1 with Size 2 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] received securityModeComplete on UL-DCCH 1 from UE [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Logical Channel DL-DCCH, Generate UECapabilityEnquiry (bytes 3) [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI a19]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 1, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19][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][eNB 0] Frame 437: received a DCCH 1 message on SRB 1 with Size 73 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] received ueCapabilityInformation on UL-DCCH 1 from UE [RRC][I]got UE capabilities for UE a19 [SCTP][I][sctp_send_data] Successfully sent 100 bytes on stream 1 for assoc_id 18 [RRC][I]RRCConnectionReconfiguration Encoded 1076 bits (135 bytes) [RRC][I][eNB 0] Frame 0, Logical Channel DL-DCCH, Generate RRCConnectionReconfiguration (bytes 135, UE id a19) [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI a19]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 2, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19][SRB AM 01] RLC_AM_DATA_REQ size 140 Bytes, NB SDU 5 current_sdu_index=4 next_sdu_index=5 conf 0 mui 2 vtA 5 vtS 5 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [RRC][N][eNB 0] Frame 467: received a DCCH 1 message on SRB 1 with Size 2 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] UE State = RRC_RECONFIGURED (default DRB, xid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI a19][SRB 02] Action ADD LCID 2 (SRB id 2) configured with SN size 5 bits and RLC AM [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI a19][DRB 01] Action ADD LCID 3 (DRB id 1) configured with SN size 12 bits and RLC UM [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19] [SRB 2] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19][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 00000][eNB][MOD 00][RNTI a19] [DRB 1] rrc_rlc_add_rlc DRB [RRC][I][eNB 0] Frame 0 CC 0 : SRB2 is now active [RRC][I][eNB 0] Frame 0 : Logical Channel UL-DCCH, Received RRCConnectionReconfigurationComplete from UE rnti a19, reconfiguring DRB 1/LCID 3 [RRC][I][eNB 0] Frame 0 : Logical Channel UL-DCCH, Received RRCConnectionReconfigurationComplete from UE 0, reconfiguring DRB 1/LCID 3 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 0 (a19) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd400a1c0 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [S1AP][I][s1ap_eNB_initial_ctxt_resp] initial_ctxt_resp_p: e_rab ID 5, enb_addr 192.168.0.70, SIZE 4 [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd400a1c0 for UE 0 [SCTP][I][sctp_send_data] Successfully sent 40 bytes on stream 1 for assoc_id 18 [RLC][W][FRAME 00478][eNB][MOD 00][RNTI a19][SRB AM 01][RLC AM MAX RETX=5] SN 0005 [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [RRC][N][eNB 0] Frame 508: received a DCCH 2 message on SRB 2 with Size 16 from UE a19 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Received on DCCH 2 RRC_DCCH_DATA_IND [MAC][I][schedule_ue_spec] [eNB 0], Frame 508, DCCH1->DLSCH, CC_id 0, Requesting 283 bytes from RLC (RRC message) [SCTP][I][sctp_send_data] Successfully sent 61 bytes on stream 1 for assoc_id 18 [MAC][I][schedule_ue_spec] [eNB 0][DLSCH] Frame 509 Generate header for UE_id 0 on CC_id 0: sdu_length_total 0, num_sdus 1, sdu_lengths[0] 0, sdu_lcids[0] 1 => payload offset 4,timing advance value : 3, padding 1,post_padding 0,(mcs 0, TBS 4, nb_rb 2),header_dcch 1, header_dtch 0 [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ue_spec] [eNB 0], Frame 526, DCCH1->DLSCH, CC_id 0, Requesting 283 bytes from RLC (RRC message) [MAC][I][schedule_ue_spec] [eNB 0][DLSCH] Frame 528 Generate header for UE_id 0 on CC_id 0: sdu_length_total 0, num_sdus 1, sdu_lengths[0] 0, sdu_lcids[0] 1 => payload offset 4,timing advance value : 3, padding 1,post_padding 0,(mcs 0, TBS 4, nb_rb 2),header_dcch 1, header_dtch 0 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [PHY][W][eNB 0, CC 0] frame 592, subframe 8, UE 0: ULSCH consecutive error count reached 20, triggering UL Failure [MAC][I][UL_failure_indication] [eNB 0][UE 0/a19] Frame 592 subframeP 8 Signaling UL Failure for UE 0 on CC_id 0 (timer 0) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [MAC][I][eNB_dlsch_ulsch_scheduler] UE 0 rnti a19: UL Failure after repeated PDCCH orders: Triggering RRC [RRC][I]Frame 612, Subframe 7: UE a19 UL failure, activating timer MAC: remove UE 0 rnti a19 [MAC][I][rrc_mac_remove_ue] Removing UE 0 from Primary CC_id 0 (rnti a19) [PHY][I][eNB 0][RAPROC] Frame 613 Terminating ra_proc for harq 3, UE 1 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 613, Received CCCH: 1.43.20.4.90.18, Terminating RA procedure for UE rnti 1fa4 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 613 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 0 rnti 1fa4 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 613 Added user with rnti 1fa4 => UE 0 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 613 subfarme 5, UE 0: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 1fa4] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 1fa4] RRCConnectionReestablishmentRequest cause Other Failure [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 1fa4] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionReestablishmentReject (bytes 1) [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 613 subfarme 6, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 613 subfarme 7, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 613 subfarme 8, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 613 subfarme 9, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 614, subframeP 0: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 1fa4) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 614 subframeP 0 Msg4 : TBS 22, sdu_len 1, msg4_header 8, msg4_padding 0, msg4_post_padding 12 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 614 subfarme 0, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 614 subfarme 1, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 614 subfarme 2, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 614 subfarme 3, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 614 subfarme 4, UE 0: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 614, subframeP 5: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 1fa4 fsf 614/5, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 614, subframeP 5 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 614 subframeP 5 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 617 subframeP 7 Scheduled UE 0 (mcs 10, first rb 8, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 620 subframeP 9 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 624 subframeP 1 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 627 subframeP 3 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 630 subframeP 5 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 633 subframeP 7 Scheduled UE 0 (mcs 10, first rb 8, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 636 subframeP 9 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 640 subframeP 1 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 643 subframeP 3 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 646 subframeP 5 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 649 subframeP 7 Scheduled UE 0 (mcs 10, first rb 8, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 652 subframeP 9 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 656 subframeP 1 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 659 subframeP 3 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [PHY][I][eNB 0][RAPROC] Frame 659 Terminating ra_proc for harq 7, UE 0 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 659, Received CCCH: 58.16.14.83.6e.62, Terminating RA procedure for UE rnti 5306 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 659 CCCH: Received Msg3: length 6, offset 3 MAC: new UE id 1 rnti 5306 [MAC][I][rx_sdu] [eNB 0][RAPROC] CC_id 0 Frame 659 Added user with rnti 5306 => UE 1 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 659 subfarme 5, UE 1: not configured, skipping UE scheduling [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] Received RRC_MAC_CCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] Accept new connection from UE random UE identity (0xe636486181000000) MME code 0 TMSI 0 cause 1 [MAC][I][rrc_mac_config_req] [CONFIG][eNB 0/0] Configuring MAC/PHY for UE 1 (5306) [PHY][I]phy_config_dedicated_eNB: physicalConfigDedicated=0x7f9dd40d8bc0 [PHY][I]Transmission Mode (phy_config_dedicated_eNB) 1 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] [RAPROC] Logical Channel DL-CCCH, Generating RRCConnectionSetup (bytes 25) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306]CALLING RLC CONFIG SRB1 (rbid 1) [PDCP][N][FRAME 00000][eNB][MOD 00][RNTI 5306][SRB 01] Action ADD LCID 1 (SRB id 1) configured with SN size 5 bits and RLC AM [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 659 subfarme 6, UE 1: not configured, skipping UE scheduling [PHY][I][eNB 0] Sent physicalConfigDedicated=0x7f9dd40d8bc0 for UE 0 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] [SRB 1] rrc_rlc_add_rlc SRB [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 5306][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][schedule_ulsch_rnti] [eNB 0] frame 659 subfarme 7, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 659 subfarme 8, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 659 subfarme 9, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 660, subframeP 0: Generating Msg4 with RRC Piggyback (RA proc 0, RNTI 5306) [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 660 subframeP 0 Msg4 : TBS 41, sdu_len 25, msg4_header 8, msg4_padding 0, msg4_post_padding 7 [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 660 subfarme 0, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 660 subfarme 1, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 660 subfarme 2, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 660 subfarme 3, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_ulsch_rnti] [eNB 0] frame 660 subfarme 4, UE 1: not configured, skipping UE scheduling [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 660, subframeP 5: Checking if Msg4 was acknowledged: MAC: msg4 acknowledged for rnti 5306 fsf 660/5, let's configure it [MAC][I][schedule_RA] [eNB 0][RAPROC] CC_id 0 Frame 660, subframeP 5 : Msg4 acknowledged [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 1/5306] CC_id 0 Frame 660 subframeP 5 Scheduled UE 1 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 1) [MAC][I][SR_indication] [eNB 0][SR 5306] Frame 661 subframeP 1 Signaling SR for UE 1 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 3/5306] CC_id 0 Frame 661 subframeP 5 Scheduled UE 1 (mcs 0, first rb 1, nb_rb 3, rb_table_index 2, TBS 7, harq_pid 3) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][rx_sdu] [eNB 0] CC_id 0 MAC CE_LCID 29 : ul_total_buffer = 105 (lcg increment 105) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 3/5306] CC_id 0 Frame 662 subframeP 3 Scheduled UE 1 (mcs 10, first rb 1, nb_rb 5, rb_table_index 4, TBS 109, harq_pid 3) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 4/5306] CC_id 0 Frame 662 subframeP 4 Scheduled UE 1 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 4) [MAC][I][SR_indication] [eNB 0][SR 5306] Frame 662 subframeP 1 Signaling SR for UE 1 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/5306] CC_id 0 Frame 662 subframeP 5 Scheduled UE 1 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [MAC][I][allocate_CCEs] subframe 5: Dropping Allocation for RNTI 1fa4 (DCI 3/4) [MAC][I][allocate_CCEs] DCI 0/4 : rnti ffff dci format 2, aggreg 4 nCCE 16 / 21 (num_pdcch_symbols 3) [MAC][I][allocate_CCEs] DCI 1/4 : rnti 2 dci format 2, aggreg 4 nCCE 16 / 21 (num_pdcch_symbols 3) [MAC][I][allocate_CCEs] DCI 2/4 : rnti 5306 dci format 0, aggreg 8 nCCE 16 / 21 (num_pdcch_symbols 3) [MAC][I][allocate_CCEs] DCI 3/4 : rnti 1fa4 dci format 0, aggreg 8 nCCE 16 / 21 (num_pdcch_symbols 3) [MAC][W][schedule_ulsch_rnti] [eNB 0] frame 662 subframe 5, UE 0/1fa4 CC 0: not enough nCCE [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/5306] CC_id 0 Frame 662 subframeP 6 Scheduled UE 1 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 6) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 6/1fa4] CC_id 0 Frame 662 subframeP 6 Scheduled UE 0 (mcs 10, first rb 4, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 6) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 7/5306] CC_id 0 Frame 662 subframeP 7 Scheduled UE 1 (mcs 10, first rb 2, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 7) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 0/5306] CC_id 0 Frame 662 subframeP 8 Scheduled UE 1 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 0) [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 662 subframeP 5 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 1/1fa4] CC_id 0 Frame 662 subframeP 9 Scheduled UE 0 (mcs 10, first rb 4, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 1) [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 2/5306] CC_id 0 Frame 663 subframeP 0 Scheduled UE 1 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 2) [MAC][I][rx_sdu] [eNB 0] CC_id 0 MAC CE_LCID 29 : ul_total_buffer = 0 (lcg increment 0) [RRC][N][eNB 0] Frame 662: received a DCCH 1 message on SRB 1 with Size 96 from UE 5306 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] Received on DCCH 1 RRC_DCCH_DATA_IND [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] [RAPROC] Logical Channel UL-DCCH, processing RRCConnectionSetupComplete from UE (SRB1 Active) [S1AP][I][rrc_eNB_send_S1AP_NAS_FIRST_REQ] [eNB 0] Build S1AP_NAS_FIRST_REQ adding in s_TMSI: GUMMEI mme_code 1 mme_group_id 4 ue 5306 [S1AP][I][s1ap_eNB_handle_nas_first_req] Found usable eNB_ue_s1ap_id: 0xfa3950 16398672(10) [S1AP][I][s1ap_eNB_handle_nas_first_req] GUMMEI_ID_PRESENT [SCTP][I][sctp_send_data] Successfully sent 148 bytes on stream 1 for assoc_id 18 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] UE State = RRC_CONNECTED [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 22 received from port 36412, on stream 1, PPID 18 [S1AP][I][s1ap_decode_s1ap_uecontextreleasecommandies] Decoding message S1ap_UEContextReleaseCommandIEs (/home/up/openairinterface5g/cmake_targets/lte_build_oai/build/CMakeFiles/R10.5/s1ap_decoder.c:5937) [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Logical Channel DL-DCCH, Generate RRCConnectionRelease (bytes 3) [S1AP][W][s1ap_ue_context_release_complete] Removed UE context eNB_ue_s1ap_id 420141 [SCTP][I][sctp_send_data] Successfully sent 21 bytes on stream 1 for assoc_id 18 [RRC][W]S1AP removed entry in hashtable s1ap_id2_s1ap_ids for eNB_ue_s1ap_id 420141 [RRC][W]S1AP removed entry in hashtable initial_id2_s1ap_ids for ue_initial_id 1 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI a19]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 3, confirmP 0, mode 1 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 29 received from port 36412, on stream 1, PPID 18 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI a19][SRB AM 01] RLC_AM_DATA_REQ size 8 Bytes, NB SDU 6 current_sdu_index=5 next_sdu_index=6 conf 0 mui 3 vtA 5 vtS 6 [S1AP][I][s1ap_decode_s1ap_downlinknastransporties] Decoding message S1ap_DownlinkNASTransportIEs (/home/up/openairinterface5g/cmake_targets/lte_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 16398672 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 5306]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 4, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 5306][SRB AM 01] RLC_AM_DATA_REQ size 11 Bytes, NB SDU 1 current_sdu_index=0 next_sdu_index=1 conf 0 mui 4 vtA 0 vtS 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 1/1fa4] CC_id 0 Frame 666 subframeP 1 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 1) [RRC][N][eNB 0] Frame 665: received a DCCH 1 message on SRB 1 with Size 20 from UE 5306 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI 5306] Received on DCCH 1 RRC_DCCH_DATA_IND [SCTP][I][sctp_send_data] Successfully sent 65 bytes on stream 1 for assoc_id 18 [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 1/1fa4] CC_id 0 Frame 669 subframeP 3 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 1) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 671 subframeP 5 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 3/1fa4] CC_id 0 Frame 671 subframeP 9 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 3) [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] Received notification for sd 41, type 32777 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I][s1ap_decode_s1ap_downlinknastransporties] Decoding message S1ap_DownlinkNASTransportIEs (/home/up/openairinterface5g/cmake_targets/lte_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 16398672 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 5306]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 4, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 5306][SRB AM 01] RLC_AM_DATA_REQ size 44 Bytes, NB SDU 2 current_sdu_index=1 next_sdu_index=2 conf 0 mui 4 vtA 1 vtS 1 [MAC][I][schedule_ue_spec] [eNB 0][DLSCH] Frame 672 Generate header for UE_id 1 on CC_id 0: sdu_length_total 46, num_sdus 1, sdu_lengths[0] 46, sdu_lcids[0] 1 => payload offset 5,timing advance value : 3, padding 0,post_padding 5,(mcs 13, TBS 55, nb_rb 2),header_dcch 2, header_dtch 0 [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 672 subframeP 5 Signaling SR for UE 0 on CC_id 0 [MAC][I][schedule_ulsch_rnti] [eNB 0][PUSCH 5/1fa4] CC_id 0 Frame 672 subframeP 9 Scheduled UE 0 (mcs 10, first rb 1, nb_rb 3, rb_table_index 2, TBS 63, harq_pid 5) [RRC][I]Removing UE a19 instance [RRC][W][eNB 0] Removing UE RNTI a19 MAC: cannot remove UE rnti a19 [MAC][W][rrc_mac_remove_ue] rrc_mac_remove_ue: UE a19 not found [S1AP][W][s1ap_ue_context_release_req] Failed to find ue context associated with eNB ue s1ap id: 420141 [S1AP][E][s1ap_eNB_task] Failed to find ue context associated with eNB ue s1ap id: 420141 [RRC][I][FRAME 00000][eNB][MOD 00][RNTI a19] Removed UE context [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [PHY][W][eNB 0, CC 0] frame 675, subframe 1, UE 1: ULSCH consecutive error count reached 20, triggering UL Failure [MAC][I][UL_failure_indication] [eNB 0][UE 0/1fa4] Frame 675 subframeP 1 Signaling UL Failure for UE 0 on CC_id 0 (timer 0) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 679 subframeP 5 Signaling SR for UE 0 on CC_id 0 [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 685 subframeP 5 Signaling SR for UE 0 on CC_id 0 [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 688 subframeP 5 Signaling SR for UE 0 on CC_id 0 [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [MAC][I][SR_indication] [eNB 0][SR 1fa4] Frame 692 subframeP 5 Signaling SR for UE 0 on CC_id 0 [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][I][eNB_dlsch_ulsch_scheduler] UE 0 rnti 1fa4: UL Failure after repeated PDCCH orders: Triggering RRC [RRC][W]Frame 695, Subframe 0: UL failure: UE 1fa4 unknown MAC: remove UE 0 rnti 1fa4 [MAC][I][rrc_mac_remove_ue] Removing UE 0 from Primary CC_id 0 (rnti 1fa4) [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [MAC][E][schedule_ulsch] scheduled retransmission in forbidden RBs [PHY][W][eNB 0, CC 0] frame 740, subframe 5, UE 0: ULSCH consecutive error count reached 20, triggering UL Failure [MAC][I][UL_failure_indication] [eNB 0][UE 1/5306] Frame 740 subframeP 5 Signaling UL Failure for UE 1 on CC_id 0 (timer 0) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [PHY][E]ERROR: Format 1A: rb_alloc (1ff) > RIV_max (144) [MAC][I][eNB_dlsch_ulsch_scheduler] UE 1 rnti 5306: UL Failure after repeated PDCCH orders: Triggering RRC [RRC][I]Frame 760, Subframe 4: UE 5306 UL failure, activating timer MAC: remove UE 1 rnti 5306 [MAC][I][rrc_mac_remove_ue] Removing UE 1 from Primary CC_id 0 (rnti 5306) [RRC][I]UE rnti 5306 failure timer 2637/20000 [SCTP][I][sctp_eNB_flush_sockets] Found data for descriptor 41 [SCTP][I][sctp_eNB_read_from_socket] [18][41] Msg of length 62 received from port 36412, on stream 1, PPID 18 [S1AP][I][s1ap_decode_s1ap_downlinknastransporties] Decoding message S1ap_DownlinkNASTransportIEs (/home/up/openairinterface5g/cmake_targets/lte_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 16398672 [PDCP][I][FRAME 00000][eNB][MOD 00][RNTI 5306]Received RRC_DCCH_DATA_REQ from TASK_RRC_ENB: instance 0, rb_id 1, muiP 4, confirmP 0, mode 1 [RLC][I][FRAME 00000][eNB][MOD 00][RNTI 5306][SRB AM 01] RLC_AM_DATA_REQ size 44 Bytes, NB SDU 3 current_sdu_index=2 next_sdu_index=3 conf 0 mui 4 vtA 2 vtS 2