root@nrtricpoc:~/RAN/riaB/sdran-in-a-box# make test-user-plane Helm values.yaml file: /root/RAN/riaB/sdran-in-a-box//sdran-in-a-box-values-master-stable.yaml HEAD is now at 9f79ab8 Fix the default SRIOV resource name for UPF user plane interfaces HEAD is now at b3659f4 Bumping chart versions (#1131) *** T1: Internal network test: ping 192.168.250.1 (Internal router IP) *** PING 192.168.250.1 (192.168.250.1) from 172.250.255.254 oaitun_ue1: 56(84) bytes of data. --- 192.168.250.1 ping statistics --- 3 packets transmitted, 0 received, 100% packet loss, time 2036ms *** T2: Internet connectivity test: ping to 8.8.8.8 *** PING 8.8.8.8 (8.8.8.8) from 172.250.255.254 oaitun_ue1: 56(84) bytes of data. --- 8.8.8.8 ping statistics --- 3 packets transmitted, 0 received, 100% packet loss, time 2029ms *** T3: DNS test: ping to google.com *** PING google.com (172.217.15.110) from 172.250.255.254 oaitun_ue1: 56(84) bytes of data. --- google.com ping statistics --- 3 packets transmitted, 0 received, 100% packet loss, time 2054ms mk/test-cases.mk:8: recipe for target 'test-user-plane' failed make: *** [test-user-plane] Error 1 root@nrtricpoc:~/RAN/riaB/sdran-in-a-box# kubectl get pods -A NAMESPACE NAME READY STATUS RESTARTS AGE default router 1/1 Running 0 8m55s kube-system atomix-controller-6989fbdbf-kwf4t 1/1 Running 0 8m2s kube-system atomix-raft-storage-controller-746fbdb557-pt2bz 1/1 Running 0 7m45s kube-system calico-kube-controllers-59466bfc9b-j5nzv 1/1 Running 0 11m kube-system calico-node-65dgh 1/1 Running 0 11m kube-system coredns-bbb7d66cd-6d9td 1/1 Running 0 11m kube-system dns-autoscaler-6f895b87bc-w7cmt 1/1 Running 0 11m kube-system kube-apiserver-node1 1/1 Running 0 12m kube-system kube-controller-manager-node1 1/1 Running 1 12m kube-system kube-multus-ds-amd64-kdfzh 1/1 Running 0 11m kube-system kube-proxy-d2srx 1/1 Running 0 11m kube-system kube-scheduler-node1 1/1 Running 1 12m kube-system nodelocaldns-5jtg4 1/1 Running 0 11m kube-system onos-operator-app-78f8f6b998-dpg5w 1/1 Running 0 7m32s kube-system onos-operator-topo-7dc455b468-pxp24 1/1 Running 0 7m32s riab cassandra-0 1/1 Running 0 7m7s riab hss-0 1/1 Running 0 7m8s riab mme-0 4/4 Running 0 7m8s riab oai-enb-cu-0 1/1 Running 0 5m riab oai-enb-du-0 1/1 Running 1 3m48s riab oai-ue-0 1/1 Running 0 2m36s riab onos-a1t-77954946fc-4pcnb 2/2 Running 0 6m3s riab onos-cli-64988df4d9-kvhlv 1/1 Running 0 6m3s riab onos-config-5cf5d77449-87hhf 4/4 Running 0 6m3s riab onos-consensus-store-0 1/1 Running 0 6m2s riab onos-e2t-5b9c6df69-7bjkn 3/3 Running 0 6m3s riab onos-kpimon-5b6f976bf9-x8vr2 2/2 Running 0 6m3s riab onos-rsm-6c9d759466-hlnhn 2/2 Running 0 6m3s riab onos-topo-56df7985d6-ltkl6 3/3 Running 0 6m3s riab onos-uenib-6c8c644f54-v8j27 3/3 Running 0 6m3s riab pcrf-0 1/1 Running 0 7m7s riab spgwc-0 2/2 Running 0 7m7s riab upf-0 4/4 Running 0 6m21s root@nrtricpoc:~/RAN/riaB/sdran-in-a-box# make test-kpimon Helm values.yaml file: /root/RAN/riaB/sdran-in-a-box//sdran-in-a-box-values-master-stable.yaml HEAD is now at 9f79ab8 Fix the default SRIOV resource name for UPF user plane interfaces HEAD is now at b3659f4 Bumping chart versions (#1131) *** Get KPIMON result through CLI *** Node ID Cell Object ID Cell Global ID Time RRC.ConnEstabAtt.sum RRC.ConnEstabSucc.sum RRC.ConnMax RRC.ConnMean RRC.ConnReEstabAtt.sum e2:4/e00/2/64 1 e0000 06:37:53.0 2 1 2 1 0 root@nrtricpoc:~/RAN/riaB/sdran-in-a-box# make test-rsm-dataplane Helm values.yaml file: /root/RAN/riaB/sdran-in-a-box//sdran-in-a-box-values-master-stable.yaml HEAD is now at 9f79ab8 Fix the default SRIOV resource name for UPF user plane interfaces HEAD is now at b3659f4 Bumping chart versions (#1131) *** Test downlink traffic (UDP) *** sudo apt install -y iperf3 Reading package lists... Done Building dependency tree Reading state information... Done iperf3 is already the newest version (3.1.3-1). The following packages were automatically installed and are no longer required: python-argcomplete python-ipaddr Use 'sudo apt autoremove' to remove them. 0 upgraded, 0 newly installed, 0 to remove and 22 not upgraded. kubectl exec -it router -- apt install -y iperf3 Reading package lists... Done Building dependency tree Reading state information... Done The following extra packages will be installed: libiperf0 The following NEW packages will be installed: iperf3 libiperf0 0 upgraded, 2 newly installed, 0 to remove and 80 not upgraded. Need to get 56.7 kB of archives. After this operation, 236 kB of additional disk space will be used. Get:1 http://archive.ubuntu.com/ubuntu/ trusty-backports/universe libiperf0 amd64 3.0.7-1~ubuntu14.04.1 [48.7 kB] Get:2 http://archive.ubuntu.com/ubuntu/ trusty-backports/universe iperf3 amd64 3.0.7-1~ubuntu14.04.1 [7966 B] Fetched 56.7 kB in 0s (347 kB/s) Selecting previously unselected package libiperf0. (Reading database ... 17318 files and directories currently installed.) Preparing to unpack .../libiperf0_3.0.7-1~ubuntu14.04.1_amd64.deb ... Unpacking libiperf0 (3.0.7-1~ubuntu14.04.1) ... Selecting previously unselected package iperf3. Preparing to unpack .../iperf3_3.0.7-1~ubuntu14.04.1_amd64.deb ... Unpacking iperf3 (3.0.7-1~ubuntu14.04.1) ... Setting up libiperf0 (3.0.7-1~ubuntu14.04.1) ... Setting up iperf3 (3.0.7-1~ubuntu14.04.1) ... Processing triggers for libc-bin (2.19-0ubuntu6.13) ... iperf3 -s -B $(ip a show oaitun_ue1 | grep inet | grep -v inet6 | awk '{print $2}' | awk -F '/' '{print $1}') -p 5001 > /dev/null & kubectl exec -it router -- iperf3 -u -c $(ip a show oaitun_ue1 | grep inet | grep -v inet6 | awk '{print $2}' | awk -F '/' '{print $1}') -p 5001 -b 20M -l 1450 -O 2 -t 12 --get-server-output iperf3: error - unable to connect to server: Connection timed out command terminated with exit code 1 mk/test-cases.mk:44: recipe for target 'test-rsm-dataplane' failed make: *** [test-rsm-dataplane] Error 1 root@nrtricpoc:~/RAN/riaB/sdran-in-a-box# kubectl logs -f oai-enb-du-0 -n riab --previous + ENODEB=1 + /opt/oai/bin/lte-softmodem -O /opt/oai/share/du.conf [LOADER] library libNB_IoT.so is not loaded: libNB_IoT.so: cannot open shared object file: No such file or directory [CONFIG] get parameters from libconfig /opt/oai/share/du.conf , debug flags: 0x00000000 [CONFIG] function config_libconfig_init returned 0 [CONFIG] config module libconfig loaded [LIBCONFIG] config: 1/1 parameters successfully set, (1 to default value) # /dev/cpu_dma_latency set to 0us [LIBCONFIG] log_config: 3/3 parameters successfully set, (1 to default value) [LIBCONFIG] log_config: 53/53 parameters successfully set, (48 to default value) [LIBCONFIG] log_config: 53/53 parameters successfully set, (53 to default value) [LIBCONFIG] log_config: 15/15 parameters successfully set, (15 to default value) [LIBCONFIG] log_config: 15/15 parameters successfully set, (15 to default value) log init done Reading in command-line options [LIBCONFIG] (root): 23/23 parameters successfully set, (19 to default value) [LIBCONFIG] (root): 5/5 parameters successfully set, (4 to default value) Getting ENBSParams [LIBCONFIG] (root): 3/3 parameters successfully set, (1 to default value) [LIBCONFIG] list L1s not found in config file /opt/oai/share/du.conf [LIBCONFIG] list RUs not found in config file /opt/oai/share/du.conf [LIBCONFIG] THREAD_STRUCT.[0]: 2/2 parameters successfully set, (0 to default value) [CONFIG] parallel_conf is set to 2 [LIBCONFIG] THREAD_STRUCT.[0]: 2/2 parameters successfully set, (0 to default value) [CONFIG] worker_conf is set to 1 Configuration: nb_rrc_inst 1, nb_L1_inst 0, nb_ru 0 [LIBCONFIG] loader: 2/2 parameters successfully set, (2 to default value) [LIBCONFIG] loader.NB_IoT: 2/2 parameters successfully set, (1 to default value) nb_nbiot_rrc_inst 0, nb_nbiot_L1_inst 0, nb_nbiot_macrlc_inst 0 [LIBCONFIG] TTracer: 4/4 parameters successfully set, (4 to default value) configuring for RAU/RRU CPU Freq is 2.095130 ITTI init, useMME: 1 [TMR] Starting itti queue: TASK_UNKNOWN as task 0 [TMR] Starting itti queue: TASK_TIMER as task 1 [TMR] Starting itti queue: TASK_L2L1 as task 2 [TMR] Starting itti queue: TASK_BM as task 3 [TMR] Starting itti queue: TASK_PHY_ENB as task 4 [TMR] Starting itti queue: TASK_MAC_ENB as task 5 [TMR] Starting itti queue: TASK_RLC_ENB as task 6 [TMR] Starting itti queue: TASK_RRC_ENB_NB_IoT as task 7 [TMR] Starting itti queue: TASK_PDCP_ENB as task 8 [TMR] Starting itti queue: TASK_DATA_FORWARDING as task 9 [TMR] Starting itti queue: TASK_END_MARKER as task 10 [TMR] Starting itti queue: TASK_RRC_ENB as task 11 [TMR] Starting itti queue: TASK_RRC_GNB as task 12 [TMR] Starting itti queue: TASK_RAL_ENB as task 13 [TMR] Starting itti queue: TASK_S1AP as task 14 [TMR] Starting itti queue: TASK_X2AP as task 15 [TMR] Starting itti queue: TASK_M2AP_ENB as task 16 [TMR] Starting itti queue: TASK_M2AP_MCE as task 17 [TMR] Starting itti queue: TASK_M3AP as task 18 [TMR] Starting itti queue: TASK_M3AP_MME as task 19 [TMR] Starting itti queue: TASK_M3AP_MCE as task 20 [TMR] Starting itti queue: TASK_SCTP as task 21 [TMR] Starting itti queue: TASK_ENB_APP as task 22 [TMR] Starting itti queue: TASK_GNB_APP as task 23 [TMR] Starting itti queue: TASK_MCE_APP as task 24 [TMR] Starting itti queue: TASK_MME_APP as task 25 [TMR] Starting itti queue: TASK_FLEXRAN_AGENT as task 26 [TMR] Starting itti queue: TASK_PHY_UE as task 27 [TMR] Starting itti queue: TASK_MAC_UE as task 28 [TMR] Starting itti queue: TASK_RLC_UE as task 29 [TMR] Starting itti queue: TASK_PDCP_UE as task 30 [TMR] Starting itti queue: TASK_RRC_UE as task 31 [TMR] Starting itti queue: TASK_NAS_UE as task 32 [TMR] Starting itti queue: TASK_RAL_UE as task 33 [TMR] Starting itti queue: TASK_MSC as task 34 [TMR] Starting itti queue: TASK_GTPV1_U as task 35 [TMR] Starting itti queue: TASK_UDP as task 36 [TMR] Starting itti queue: TASK_CU_F1 as task 37 [TMR] Starting itti queue: TASK_DU_F1 as task 38 [TMR] Starting itti queue: TASK_RIC_AGENT as task 39 [TMR] Starting itti queue: TASK_RIC_AGENT_DU as task 40 [LIBCONFIG] opt: 3/3 parameters successfully set, (3 to default value) [OPT] OPT disabled reported resolution = 1 ns [HW] Version: Branch: develop-onf Abrev. Hash: 0227937 Date: Thu Mar 17 22:47:36 2022 +0900 Runtime table [PHY] RC.eNB = 0x39d9720 [LIBCONFIG] list L1s not found in config file /opt/oai/share/du.conf [PHY] No L1s configuration found[PHY] RC.eNB[0] = 0x39d97f0 [PHY] RC.eNB[0][0] = 0x7f2876577010 [PHY] read_config_and_init() RC.nb_L1_inst: 0 [LIBCONFIG] MACRLCs.[0]: 21/21 parameters successfully set, (4 to default value) [LIBCONFIG] MACRLCs.[0]: 21/21 parameters successfully set, (4 to default value) [MAC] [MAIN] Init function start:nb_macrlc_inst=1 [PDCP] PDCP layer has been initialized Configuring F1 interfaces for MACRLC [ENB_APP] **************** vnf_port:50001 [ENB_APP] nfapi running mode: VNF 3780.485580: 0x04: 2031998784: [VNF] configure_nfapi_vnf() vnf.p7_vnfs[0].config:0x39faf60 VNF ADDRESS:10.0.0.7:50001 3780.485599: 0x04: 2031998784: [VNF] Creating VNF NFAPI start thread configure_nfapi_vnf 3780.510921: 0x04: 2031998784: [VNF] Created VNF NFAPI start thread configure_nfapi_vnf [ENB_APP] **************** RETURNED FROM configure_nfapi_vnf() vnf_port:50001 [ENB_APP] sched mode = default 0 [default] [ENB_APP] using default scheduler DL algo 'round_robin_dl' [MAC] read_config_and_init() RC.nb_macrlc_inst: 1 [LIBCONFIG] (root): 3/3 parameters successfully set, (1 to default value) [LIBCONFIG] eNBs.[0]: 20/20 parameters successfully set, (11 to default value) [RRC] Instance 0: Southbound Transport local_mac enb_id:3584 [RRC] Setting node_type to ngran_eNB_DU gNB_CU_name[0] eNB-Eurecom-DU my_addr:192.168.200.22 [LIBCONFIG] eNBs.[0].plmn_list.[0]: 3/3 parameters successfully set, (0 to default value) [RRC] num component carriers 1 [RRC] enb_config::RCconfig_RRC() parameter number: 0, total number of parameters: 78, ccspath: eNBs.[0].component_carriers.[0] [LIBCONFIG] eNBs.[0].component_carriers.[0]: 78/78 parameters successfully set, (62 to default value) [RRC] Node type 6 [LIBCONFIG] (root): 3/3 parameters successfully set, (1 to default value) [LIBCONFIG] NETWORK_CONTROLLER: 6/6 parameters successfully set, (0 to default value) [LIBCONFIG] eNBs.[0].RIC: 3/3 parameters successfully set, (0 to default value) [RIC_AGENT] NODE[6] enabled for NB 0 [FLEXRAN_AGENT] FlexRAN Agent for eNB 0 is DISABLED [ENB_APP] Creating ENB_APP eNB Task [TMR] Created Posix thread TASK_ENB_APP [RRC] Creating RRC eNB Task [ENB_APP] ngran_eNB_DU: Allocating ITTI message for F1AP_SETUP_REQ [LIBCONFIG] (root): 3/3 parameters successfully set, (1 to default value) [TMR] Created Posix thread TASK_RRC_ENB [LIBCONFIG] eNBs.[0]: 20/20 parameters successfully set, (11 to default value) [RRC] Entering main loop of RRC message task [LIBCONFIG] eNBs.[0].plmn_list.[0]: 3/3 parameters successfully set, (0 to default value) [ENB_APP] F1AP: gNB_DU_id[0] 3584 [ENB_APP] F1AP: gNB_DU_name[0] eNB-Eurecom-DU [ENB_APP] F1AP: tac[0] 1 [ENB_APP] F1AP: mcc[0] 208 [ENB_APP] F1AP: mnc[0] 1 [ENB_APP] F1AP: mnc_digit_length[0] 2 [ENB_APP] F1AP: nr_cellid[0] 12345678 [ENB_APP] F1AP: CU_ip4_address in DU 192.168.200.21 [ENB_APP] FIAP: CU_ip4_address in DU 0x7f28700008e9, strlen 14 [ENB_APP] F1AP: DU_ip4_address in DU 192.168.200.22 [ENB_APP] FIAP: DU_ip4_address in DU 0x7f2870000929, strlen 14 [LIBCONFIG] eNBs.[0].SCTP: 2/2 parameters successfully set, (0 to default value) [ENB_APP] ngran_eNB_DU: Waiting for basic cell configuration [SCTP] Starting SCTP layer [TMR] Created Posix thread TASK_SCTP [TMR] Created Posix thread TASK_DU_F1 [MAC] Creating MAC eNB Task [TMR] Created Posix thread TASK_MAC_ENB [MAC] Creating DU RIC Agent Task [TMR] Created Posix thread TASK_RIC_AGENT_DU [RRC] [eNB 0] Received RRC_CONFIGURATION_REQ : 0x3a0ca20 [RRC] [FRAME 00000][eNB][MOD 00][RNTI 0] Init... [MAC] Starting main loop of MAC message task [RIC_AGENT] starting DU E2 agent task [F1AP] Starting F1AP at DU 3780.513014: 0x04: 1981171456: [VNF] VNF NFAPI thread - nfapi_vnf_start()vnf_start_thread [NFAPI_VNF] VNF Setting the SCTP_INITMSG [RRC] [FRAME 00000][eNB][MOD 00][RNTI 0] Checking release [RRC] [FRAME 00000][eNB][MOD 00][RNTI 0] Rel14 RRC detected, MBMS flag 0 [RRC] [eNB 0] Node type 6 [RRC] configuration->schedulingInfoSIB1_BR_r13[CC_id] 0 [RRC] Configuring MIB (N_RB_DL 25,phich_Resource 0,phich_Duration 0) [RRC] [MIB] systemBandwidth 2, phich_duration 0, phich_resource 0, sfn 0 [RRC] [MIB] schedulingInfoSIB1 0 [RIC_AGENT] _______ [RRC] [eNB] handover active state is 0 [RRC] [eNB] eMBMS active state is 0 [RRC] [FRAME 00000][eNB][MOD 00][RNTI 0] ENB:OPENAIR RRC IN.... ORAN-E2SM-RSM 1.3.6.1.4.1.53148.1.1.2.102 RAN Slicing 0 4 4 4 [RIC_AGENT] _______ [RIC_AGENT] ------ RAN SLICING FUNC DEF ENC Len:71------- [ENB_APP] ngran_DU: Configuring Cell 0 for FDD [ENB_APP] [eNB 0] eNB_app_register via F1AP for instance 0 [LIBCONFIG] eNBs.[0]: 1/1 parameters successfully set, (1 to default value) [LIBCONFIG] gNBs.[0]: 1/1 parameters successfully set, (1 to default value) [F1AP] DU Task Received F1AP_SETUP_REQ [LIBCONFIG] eNBs.[0]: 1/1 parameters successfully set, (1 to default value) [SCTP] sctp_bindx SCTP_BINDX_ADD_ADDR socket bound to : 192.168.200.22 [SCTP] Converted ipv4 address 192.168.200.21 to network type [SCTP] connectx assoc_id 36 in progress..., used 1 addresses [SCTP] Inserted new descriptor for sd 88 in list, nb elements 1, assoc_id 36 [SCTP] Found data for descriptor 88 [SCTP] Received notification for sd 88, type 32769 [SCTP] Client association changed: 0 [SCTP] ---------------------- [SCTP] Peer addresses: [SCTP] - [192.168.200.21] [SCTP] ---------------------- [SCTP] ---------------------- [SCTP] SCTP Status: [SCTP] assoc id .....: 36 [SCTP] state ........: 4 [SCTP] instrms ......: 2 [SCTP] outstrms .....: 2 [SCTP] fragmentation : 65484 [SCTP] pending data .: 0 [SCTP] unack data ...: 0 [SCTP] rwnd .........: 106496 [SCTP] peer info : [SCTP] state ....: 2 [SCTP] cwnd .....: 131064 [SCTP] srtt .....: 0 [SCTP] rto ......: 3000 [SCTP] mtu ......: 65532 [SCTP] ---------------------- [SCTP] Comm up notified for sd 88, assigned assoc_id 36 [SCTP] Found data for descriptor 88 [PROTO_AGENT] server started at port 192.168.200.22:600 [SCTP] Received notification for sd 88, type 32776 [F1AP] DU Task Received SCTP_NEW_ASSOCIATION_RESP [F1AP] Sending ITTI message to SCTP Task [SCTP] Successfully sent 111 bytes on stream 0 for assoc_id 36 [SCTP] Found data for descriptor 88 [SCTP] Received notification for sd 88, type 32777 [SCTP] Found data for descriptor 88 [SCTP] [36][88] Msg of length 107 received from port 30923, on stream 0, PPID 62 [F1AP] DU Task Received SCTP_DATA_IND [F1AP] f1ap_decode_successful_outcome(): F1AP_ProcedureCode_id_F1Setup [F1AP] Calling handler with instance 0 [ENB_APP] Received F1AP_SETUP_RESP: associated ngran_eNB_CU eNB-CU-Eurecom-LTEBox with 1 cells to activate [ENB_APP] cells_to_activated 1, RRC instances 1 [ENB_APP] Checking cell 0, rrc inst 0 : rrc->nr_cellid bc614e, resp->nr_cellid bc614e [ENB_APP] rrc inst 0: Trying to decode SI block 0 @ 0x7f28640024f0, length 38 [ENB_APP] Extracting SI 0/2 [ENB_APP] [RRC 0] Found SIB2 in CU F1AP_SETUP_RESP message [ENB_APP] Extracting SI 1/2 [ENB_APP] [RRC 0] Found SIB3 in CU F1AP_SETUP_RESP message [ENB_APP] Configuring MAC/L1 0, carrier->sib2 0x7f2870001ea0 [MAC] Configuring MIB for instance 0, CCid 0 : (band 7,N_RB_DL 25,Nid_cell 0,p 1,DL freq 2680000000,phich_config.resource 0, phich_config.duration 0) [MAC] config_mib() NFAPI_CONFIG_REQUEST(num_tlv:16) DL_BW:25 UL_BW:25 Ncp 0,p_eNB 1,earfcn 3350,band 7,phich_resource 0 phich_duration 0 phich_power_offset 6000 PSS 6000 SSS 6000 PCI 0 PBCH repetition 0 [MAC] [CONFIG]SIB2/3 Contents (partial) [MAC] [CONFIG]pusch_config_common.n_SB = 1 [MAC] [CONFIG]pusch_config_common.hoppingMode = 0 [MAC] [CONFIG]pusch_config_common.pusch_HoppingOffset = 0 [MAC] [CONFIG]pusch_config_common.enable64QAM = 0 [MAC] [CONFIG]pusch_config_common.groupHoppingEnabled = 1 [MAC] [CONFIG]pusch_config_common.groupAssignmentPUSCH = 0 [MAC] [CONFIG]pusch_config_common.sequenceHoppingEnabled = 0 [MAC] [CONFIG]pusch_config_common.cyclicShift = 1 Waiting for PHY_config_req Waiting for PHY_config_req [VNF] pnf connection indication idx:0 [VNF] RC.eNB[0][0]. Mod_id:0 CC_id:0 nb_CC[0]:1 abstraction_flag:0 single_thread_flag:0 if_inst:(nil) RC.eNB[0][0]->if_inst->PHY_config_req is not installed - install it oai_create_enb() Waiting for eNB to become configured (by RRC/PHY) - need to wait otherwise NFAPI messages won't contain correct values Waiting for PHY_config_req [PHY] Configuring MIB for instance 0, CCid 0 : (band 7,N_RB_DL 25, N_RB_UL 25, Nid_cell 0,eNB_tx_antenna_ports 1,Ncp 0,DL freq 3350,phich_config.resource 0, phich_config.duration 0) [PHY] Initializing frame parms for N_RB_DL 25, Ncp 0, osf 1 [PHY] lte_parms.c: Setting N_RB_DL to 25, ofdm_symbol_size 512 [LIBCONFIG] loader.coding: 2/2 parameters successfully set, (1 to default value) oai_create_enb() Waiting for eNB to become configured (by RRC/PHY) - need to wait otherwise NFAPI messages won't contain correct values [LOADER] library libcoding.so successfully loaded oai_create_enb() Waiting for eNB to become configured (by RRC/PHY) - need to wait otherwise NFAPI messages won't contain correct values oai_create_enb() Waiting for eNB to become configured (by RRC/PHY) - need to wait otherwise NFAPI messages won't contain correct values oai_create_enb() Waiting for eNB to become configured (by RRC/PHY) - need to wait otherwise NFAPI messages won't contain correct values oai_create_enb() Waiting for eNB to become configured (by RRC/PHY) - need to wait otherwise NFAPI messages won't contain correct values [PHY] prach_config_common.rootSequenceIndex = 0 [PHY] prach_config_common.prach_ConfigInfo.prach_ConfigIndex = 0 [PHY] prach_config_common.prach_ConfigInfo.highSpeedFlag = 0 [PHY] prach_config_common.prach_ConfigInfo.zeroCorrelationZoneConfig = 1 [PHY] prach_config_common.prach_ConfigInfo.prach_FreqOffset = 2 [PHY] pusch_config_common.n_SB = 1 [PHY] pusch_config_common.hoppingMode = 0 [PHY] pusch_config_common.pusch_HoppingOffset = 0 [PHY] pusch_config_common.enable64QAM = 0 [PHY] pusch_config_common.ul_ReferenceSignalsPUSCH.groupHoppingEnabled = 1 [PHY] pusch_config_common.ul_ReferenceSignalsPUSCH.groupAssignmentPUSCH = 0 [PHY] pusch_config_common.ul_ReferenceSignalsPUSCH.sequenceHoppingEnabled = 0 [PHY] pusch_config_common.ul_ReferenceSignalsPUSCH.cyclicShift = 2 [PHY] eNB 0/0 configured oai_create_enb() eNB is now configured [NFAPI_VNF] nfapi_vnf_pnf_list_find : config->pnf_list:0x7f28500008c0 [NFAPI_VNF] nfapi_vnf_pnf_list_find : curr->p5_idx:0 p5_idx:0 [VNF] pnf param response idx:0 error:0 [VNF] (PHY:0) phy_config_idx:0 [VNF] (PHY:0) (RF0) 0 [VNF] (PHY:0) (RF1) 0 [VNF] (RF:0) rf_config_idx:0 [VNF] (RF:1) rf_config_idx:0 DJP:Hard coded num phy rf to 2 [NFAPI_VNF] nfapi_vnf_pnf_list_find : config->pnf_list:0x7f28500008c0 [NFAPI_VNF] nfapi_vnf_pnf_list_find : curr->p5_idx:0 p5_idx:0 [VNF] pnf config response idx:0 resp[header[phy_id:0 message_id:103 message_length:12]] [NFAPI_VNF] nfapi_vnf_pnf_list_find : config->pnf_list:0x7f28500008c0 [NFAPI_VNF] nfapi_vnf_pnf_list_find : curr->p5_idx:0 p5_idx:0 [VNF] pnf start response idx:0 config:0x39fb0a0 user_data:0x163dd80 p7_vnf[config:0x39faf60 thread_started:0] [VNF] Sending NFAPI_PARAM_REQUEST phy_id:1 [NFAPI_VNF] nfapi_vnf_pnf_list_find : config->pnf_list:0x7f28500008c0 [NFAPI_VNF] nfapi_vnf_pnf_list_find : curr->p5_idx:0 p5_idx:0 [VNF] Received NFAPI_PARAM_RESP idx:0 phy_id:1 [VNF] 0.1 pnf p7 10.0.0.7:32123 timing 32 10 0 10 [VNF] Send NFAPI_CONFIG_REQUEST [VNF] DJP local_port:50001 [VNF] DJP local_addr:10.0.0.7 [VNF] Timing window:32 [NFAPI_VNF] nfapi_vnf_pnf_list_find : config->pnf_list:0x7f28500008c0 [NFAPI_VNF] nfapi_vnf_pnf_list_find : curr->p5_idx:0 p5_idx:0 [VNF] Sent NFAPI_CONFIG_REQ num_tlv:43 [VNF] Received NFAPI_CONFIG_RESP idx:0 phy_id:1 [VNF] Calling oai_enb_init() oai_enb_init() About to call init_eNB_afterRU() [PHY] init_eNB_afterRU() RC.nb_inst:1 [PHY] RC.nb_CC[inst]:1 [PHY] RC.nb_CC[inst:0][CC_id:0]:0x7f2876577010 [PHY] [eNB 0] phy_init_lte_eNB() About to wait for eNB to be configured[PHY] [eNB 0] Initializing DL_FRAME_PARMS : N_RB_DL 25, PHICH Resource 1, PHICH Duration 0 nb_antennas_tx:0 nb_antennas_rx:0 nb_antenna_ports_eNB:1 PRACH[rootSequenceIndex:0 prach_Config_enabled:1 configIndex:0 highSpeed:0 zeroCorrelationZoneConfig:1 freqOffset:2] [PHY] [eNB 0] Initializing DL_FRAME_PARMS : N_RB_DL 25, PHICH Resource 1, PHICH Duration 0 pcfich_reg : 0,12,25,37 [PHY] Mapping RX ports from 0 RUs to eNB 0 [PHY] Overwriting eNB->prach_vars.rxsigF[0]:(nil) [PHY] Overwriting eNB->prach_vars_br.rxsigF.rxsigF[0]:(nil) [PHY] Overwriting eNB->prach_vars_br.rxsigF.rxsigF[0]:(nil) [PHY] Overwriting eNB->prach_vars_br.rxsigF.rxsigF[0]:(nil) [PHY] Overwriting eNB->prach_vars_br.rxsigF.rxsigF[0]:(nil) [PHY] eNB->num_RU:0 [PHY] init_eNB_afterRU() ************* DJP ***** eNB->frame_parms.nb_antennas_rx:0 - GOING TO HARD CODE TO 1[PHY] init_eNB_afterRU() ************* DJP ***** eNB->frame_parms.nb_antennas_tx:0 - GOING TO HARD CODE TO 1[PHY] inst 0, CC_id 0 : nb_antennas_rx 1 [PHY] Initialise transport [PHY] init_eNB_proc(inst:0) RC.nb_CC[inst]:1 [PHY] Initializing eNB processes instance:0 CC_id 0 [PHY] eNB->single_thread_flag:0 [HW] thread_top_init() called with affinity>0, but overruled by #ifndef CPU_AFFINITY. vnf_p7_start_thread() [HW] [SCHED][eNB] RXn_TXnp4_0 started on CPU 5, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 CPU_2 CPU_3 CPU_4 CPU_5 CPU_6 CPU_7 [NFAPI_VNF] nfapi_vnf_pnf_list_find : config->pnf_list:0x7f28500008c0 [NFAPI_VNF] nfapi_vnf_pnf_list_find : curr->p5_idx:0 p5_idx:0 [HW] thread_top_init() called with affinity>0, but overruled by #ifndef CPU_AFFINITY. [HW] [SCHED][eNB] RXn_TXnp4_1 started on CPU 2, sched_policy = SCHED_FIFO , priority = 99, CPU Affinity= CPU_0 CPU_1 CPU_2 CPU_3 CPU_4 CPU_5 CPU_6 CPU_7 [VNF] Send NFAPI_START_REQUEST idx:0 phy_id:1 [VNF] Received NFAPI_START_RESP idx:0 phy_id:1 [PHY] thread rxtx created id=20 [NFAPI_VNF] reallocing rx buffer 28 [NFAPI_VNF] ( 0/2) PNF to VNF !sync phy_id:1 (t1/2/3/4: 2001, 882121, 882125, 2631) txrx: 630 procT: 4 latency(us): 313 [PHY] thread rxtx created id=22 [NFAPI_VNF] ( 0/4) PNF to VNF !sync phy_id:1 (t1/2/3/4: 4000, 883634, 883635, 4097) txrx: 97 procT: 1 latency(us): 48 [NFAPI_VNF] ( 0/6) PNF to VNF !sync phy_id:1 (t1/2/3/4: 6001, 885596, 885597, 6064) txrx: 63 procT: 1 latency(us): 31 [NFAPI_VNF] ( 0/8) PNF to VNF !sync phy_id:1 (t1/2/3/4: 8001, 887603, 887604, 8082) txrx: 81 procT: 1 latency(us): 40 [NFAPI_VNF] ( 1/8) PNF to VNF !sync phy_id:1 (t1/2/3/4: 18001, 897618, 897619, 18080) txrx: 79 procT: 1 latency(us): 39 [NFAPI_VNF] ( 2/0) PNF to VNF !sync phy_id:1 (t1/2/3/4: 20001, 899619, 899620, 20072) txrx: 71 procT: 1 latency(us): 35 [NFAPI_VNF] ( 2/2) PNF to VNF !sync phy_id:1 (t1/2/3/4: 22000, 901600, 901601, 22059) txrx: 59 procT: 1 latency(us): 29 [NFAPI_VNF] ( 2/4) PNF to VNF !sync phy_id:1 (t1/2/3/4: 24001, 903591, 903593, 24058) txrx: 57 procT: 2 latency(us): 27 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment879 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 90/4) PNF to VNF !sync phy_id:1 (t1/2/3/4: 904001, 904599, 904601, 904058) txrx: 57 procT: 2 latency(us): 27 [NFAPI_VNF] ( 91/4) PNF to VNF !sync phy_id:1 (t1/2/3/4: 914001, 914588, 914589, 914085) txrx: 84 procT: 1 latency(us): 41 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 91/6) PNF to VNF !sync phy_id:1 (t1/2/3/4: 916001, 916600, 916602, 916062) txrx: 61 procT: 2 latency(us): 29 [NFAPI_VNF] ( 91/8) PNF to VNF !sync phy_id:1 (t1/2/3/4: 918001, 918602, 918604, 918057) txrx: 56 procT: 2 latency(us): 27 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 92/0) PNF to VNF !sync phy_id:1 (t1/2/3/4: 920000, 920596, 920597, 920060) txrx: 60 procT: 1 latency(us): 29 [NFAPI_VNF] ( 93/0) PNF to VNF !sync phy_id:1 (t1/2/3/4: 930001, 930606, 930607, 930075) txrx: 74 procT: 1 latency(us): 36 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 93/2) PNF to VNF !sync phy_id:1 (t1/2/3/4: 932001, 932607, 932608, 932064) txrx: 63 procT: 1 latency(us): 31 [NFAPI_VNF] ( 93/4) PNF to VNF !sync phy_id:1 (t1/2/3/4: 934001, 934577, 934578, 934058) txrx: 57 procT: 1 latency(us): 28 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 93/6) PNF to VNF !sync phy_id:1 (t1/2/3/4: 936000, 936681, 936682, 936075) txrx: 75 procT: 1 latency(us): 37 [NFAPI_VNF] ( 94/6) PNF to VNF !sync phy_id:1 (t1/2/3/4: 946000, 946618, 946620, 946086) txrx: 86 procT: 2 latency(us): 42 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 94/8) PNF to VNF !sync phy_id:1 (t1/2/3/4: 948001, 948597, 948599, 948061) txrx: 60 procT: 2 latency(us): 29 [NFAPI_VNF] ( 95/0) PNF to VNF !sync phy_id:1 (t1/2/3/4: 950000, 950589, 950590, 950056) txrx: 56 procT: 1 latency(us): 27 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 95/2) PNF to VNF !sync phy_id:1 (t1/2/3/4: 952001, 952597, 952598, 952061) txrx: 60 procT: 1 latency(us): 29 [NFAPI_VNF] ( 96/2) PNF to VNF !sync phy_id:1 (t1/2/3/4: 962001, 962583, 962584, 962082) txrx: 81 procT: 1 latency(us): 40 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 96/4) PNF to VNF !sync phy_id:1 (t1/2/3/4: 964000, 964599, 964601, 964065) txrx: 65 procT: 2 latency(us): 31 [NFAPI_VNF] ( 96/6) PNF to VNF !sync phy_id:1 (t1/2/3/4: 966001, 966596, 966597, 966059) txrx: 58 procT: 1 latency(us): 28 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 96/8) PNF to VNF !sync phy_id:1 (t1/2/3/4: 968001, 968606, 968607, 968056) txrx: 55 procT: 1 latency(us): 27 [NFAPI_VNF] ( 97/8) PNF to VNF !sync phy_id:1 (t1/2/3/4: 978001, 978605, 978606, 978071) txrx: 70 procT: 1 latency(us): 34 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 98/0) PNF to VNF !sync phy_id:1 (t1/2/3/4: 980001, 980587, 980588, 980067) txrx: 66 procT: 1 latency(us): 32 [NFAPI_VNF] ( 98/2) PNF to VNF !sync phy_id:1 (t1/2/3/4: 982001, 982593, 982594, 982070) txrx: 69 procT: 1 latency(us): 34 [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ***** Adjusting VNF SFN/SF switching to filtered mode [NFAPI_VNF] ( 98/4) 1604.842915077 PNF to VNF phy_id: 1 (t1/2/3/4: 984000, 984604, 984605, 984061) txrx: 61 procT: 1 latency(us): 30(avg: 33) offset(us): 574 filtered(us): 574 wrap[t1:0 t2:0] [NFAPI_VNF] ( 99/4) 1604.852941400 PNF to VNF phy_id: 1 (t1/2/3/4: 994001, 994614, 994615, 994088) txrx: 87 procT: 1 latency(us): 43(avg: 33) offset(us): 570 filtered(us): 573 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment1 phy->previous_sf_offset_filtered:0 phy->previous_sf_offset_filtered:0 phy->sf_offset_trend:0 [NFAPI_VNF] ( 99/6) 1604.853915712 PNF to VNF phy_id: 1 (t1/2/3/4: 996001, 995584, 995585, 996062) txrx: 61 procT: 1 latency(us): 30(avg: 33) offset(us): -447 filtered(us): -447 wrap[t1:0 t2:0] [NFAPI_VNF] ( 99/8) 1604.855908037 PNF to VNF phy_id: 1 (t1/2/3/4: 998000, 997591, 997592, 998064) txrx: 64 procT: 1 latency(us): 31(avg: 33) offset(us): -440 filtered(us): -447 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:573 phy->previous_sf_offset_filtered:573 phy->sf_offset_trend:0 [NFAPI_VNF] ( 100/0) 1604.857913761 PNF to VNF phy_id: 1 (t1/2/3/4: 1000000, 999598, 999599, 1000064) txrx: 64 procT: 1 latency(us): 31(avg: 33) offset(us): -433 filtered(us): -433 wrap[t1:0 t2:0] [NFAPI_VNF] reallocing rx buffer 72 [NFAPI_VNF] ( 101/0) 1604.867939584 PNF to VNF phy_id: 1 (t1/2/3/4: 1010000, 1009622, 1009624, 1010078) txrx: 78 procT: 2 latency(us): 38(avg: 33) offset(us): -416 filtered(us): -431 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-447 phy->previous_sf_offset_filtered:-447 phy->sf_offset_trend:0 [NFAPI_VNF] ( 101/2) 1604.869903209 PNF to VNF phy_id: 1 (t1/2/3/4: 1012000, 1011600, 1011602, 1012054) txrx: 54 procT: 2 latency(us): 26(avg: 33) offset(us): -426 filtered(us): -426 wrap[t1:0 t2:0] [NFAPI_VNF] ( 101/4) 1604.871904233 PNF to VNF phy_id: 1 (t1/2/3/4: 1014001, 1013594, 1013596, 1014059) txrx: 58 procT: 2 latency(us): 28(avg: 33) offset(us): -435 filtered(us): -428 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-431 phy->previous_sf_offset_filtered:-431 phy->sf_offset_trend:0 [NFAPI_VNF] ( 101/6) 1604.873910058 PNF to VNF phy_id: 1 (t1/2/3/4: 1016001, 1015600, 1015602, 1016056) txrx: 55 procT: 2 latency(us): 26(avg: 33) offset(us): -427 filtered(us): -427 wrap[t1:0 t2:0] [NFAPI_VNF] ( 102/6) 1604.883920581 PNF to VNF phy_id: 1 (t1/2/3/4: 1026001, 1025613, 1025614, 1026071) txrx: 70 procT: 1 latency(us): 34(avg: 33) offset(us): -422 filtered(us): -427 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-428 phy->previous_sf_offset_filtered:-428 phy->sf_offset_trend:0 [NFAPI_VNF] ( 102/8) 1604.885907305 PNF to VNF phy_id: 1 (t1/2/3/4: 1028001, 1027588, 1027590, 1028059) txrx: 58 procT: 2 latency(us): 28(avg: 33) offset(us): -441 filtered(us): -441 wrap[t1:0 t2:0] [NFAPI_VNF] ( 103/0) 1604.887913630 PNF to VNF phy_id: 1 (t1/2/3/4: 1030001, 1029591, 1029593, 1030059) txrx: 58 procT: 2 latency(us): 28(avg: 33) offset(us): -438 filtered(us): -441 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-427 phy->previous_sf_offset_filtered:-427 phy->sf_offset_trend:0 [NFAPI_VNF] ( 103/2) 1604.889906154 PNF to VNF phy_id: 1 (t1/2/3/4: 1032001, 1031588, 1031590, 1032057) txrx: 56 procT: 2 latency(us): 27(avg: 33) offset(us): -440 filtered(us): -440 wrap[t1:0 t2:0] [NFAPI_VNF] ( 104/2) 1604.899934277 PNF to VNF phy_id: 1 (t1/2/3/4: 1042001, 1041589, 1041592, 1042090) txrx: 89 procT: 3 latency(us): 43(avg: 33) offset(us): -455 filtered(us): -442 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-441 phy->previous_sf_offset_filtered:-441 phy->sf_offset_trend:434 [NFAPI_VNF] ( 104/4) 1604.901950002 PNF to VNF phy_id: 1 (t1/2/3/4: 1044001, 1043630, 1043632, 1044084) txrx: 83 procT: 2 latency(us): 40(avg: 33) offset(us): -411 filtered(us): -411 wrap[t1:0 t2:0] [NFAPI_VNF] ( 104/6) 1604.903910926 PNF to VNF phy_id: 1 (t1/2/3/4: 1046000, 1045585, 1045586, 1046061) txrx: 61 procT: 1 latency(us): 30(avg: 33) offset(us): -445 filtered(us): -416 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-442 phy->previous_sf_offset_filtered:-442 phy->sf_offset_trend:441 [NFAPI_VNF] ( 104/8) 1604.905934651 PNF to VNF phy_id: 1 (t1/2/3/4: 1048001, 1047613, 1047615, 1048082) txrx: 81 procT: 2 latency(us): 39(avg: 33) offset(us): -427 filtered(us): -427 wrap[t1:0 t2:0] [NFAPI_VNF] ( 105/8) 1604.915975074 PNF to VNF phy_id: 1 (t1/2/3/4: 1058001, 1057624, 1057627, 1058121) txrx: 120 procT: 3 latency(us): 58(avg: 33) offset(us): -435 filtered(us): -428 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-416 phy->previous_sf_offset_filtered:-416 phy->sf_offset_trend:441 [NFAPI_VNF] ( 106/0) 1604.917941298 PNF to VNF phy_id: 1 (t1/2/3/4: 1060001, 1059345, 1059349, 1060099) txrx: 98 procT: 4 latency(us): 47(avg: 33) offset(us): -703 filtered(us): -703 wrap[t1:0 t2:0] [NFAPI_VNF] ( 106/2) 1604.919897122 PNF to VNF phy_id: 1 (t1/2/3/4: 1062000, 1061585, 1061587, 1062056) txrx: 56 procT: 2 latency(us): 27(avg: 33) offset(us): -442 filtered(us): -671 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-428 phy->previous_sf_offset_filtered:-428 phy->sf_offset_trend:422 [NFAPI_VNF] ( 106/4) 1604.921899347 PNF to VNF phy_id: 1 (t1/2/3/4: 1064000, 1063581, 1063583, 1064059) txrx: 59 procT: 2 latency(us): 28(avg: 33) offset(us): -447 filtered(us): -447 wrap[t1:0 t2:0] [NFAPI_VNF] ( 107/4) 1604.931929670 PNF to VNF phy_id: 1 (t1/2/3/4: 1074000, 1073582, 1073585, 1074089) txrx: 89 procT: 3 latency(us): 43(avg: 33) offset(us): -461 filtered(us): -449 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-671 phy->previous_sf_offset_filtered:-671 phy->sf_offset_trend:549 [NFAPI_VNF] ( 107/6) 1604.933900794 PNF to VNF phy_id: 1 (t1/2/3/4: 1076000, 1075583, 1075584, 1076060) txrx: 60 procT: 1 latency(us): 29(avg: 33) offset(us): -446 filtered(us): -446 wrap[t1:0 t2:0] [NFAPI_VNF] ( 107/8) 1604.935911919 PNF to VNF phy_id: 1 (t1/2/3/4: 1078001, 1077589, 1077591, 1078072) txrx: 71 procT: 2 latency(us): 34(avg: 33) offset(us): -446 filtered(us): -446 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-449 phy->previous_sf_offset_filtered:-449 phy->sf_offset_trend:549 [NFAPI_VNF] VNF P7 In Sync with phy (phy_id:1) [VNF] SYNC ACHIEVED [VNF] Signal to OAI main code that it can go [NFAPI_VNF] ( 107/8) VNF phy_id:1 Apply minor insync adjustment -91us for 4 subframes (sf_offset_filtered:-446) 91 274 549 NEW:1078 CURR:1078 adjustment:0 [NFAPI_VNF] [VNF] AFTER adjustment - Subframe minor adjustment -91us sf_start.tv_nsec:937921326 duration:3 [VNF] subframe indication 1079 [MAC] SCHED_MODE = 0, PUSCH Target SNR:20, PUCCH Target SNR:20 [NFAPI_VNF] [VNF] AFTER adjustment - Subframe minor adjustment -91us sf_start.tv_nsec:939012326 duration:2 [NFAPI_VNF] [VNF] AFTER adjustment - Subframe minor adjustment -91us sf_start.tv_nsec:940103326 duration:1 [NFAPI_VNF] [VNF] AFTER adjustment - Subframe minor adjustment -91us sf_start.tv_nsec:941194326 duration:0 [ENB_APP] NFAPI*** - mutex and cond created - will block shortly for completion of PNF connection waiting for NFAPI PNF connection and population of global structure (main?) NFAPI: got sync (main?) [ENB_APP] START MAIN THREADS RC.nb_L1_inst:0 wait_eNBs() Waiting for eNB L1 instances to all get configured ... sleeping 50ms (nb_L1_inst 0) eNB L1 are configured About to Init RU threads RC.nb_RU:0 [MME_APP] Creating MME_APP eNB Task [TMR] Created Posix thread TASK_MME_APP [LIBCONFIG] MMEs.[0]: 1/1 parameters successfully set, (1 to default value) [MCE_APP] Creating MCE_APP eNB Task [TMR] Created Posix thread TASK_MCE_APP [LIBCONFIG] MCEs.[0]: 1/1 parameters successfully set, (1 to default value) [LIBCONFIG] MCEs.[0]: 1/1 parameters successfully set, (1 to default value) [ENB_APP] TYPE TO TERMINATE [ENB_APP] [MCE 0] MCE_app_register via M3AP for instance 0 [NFAPI_VNF] ( 150/6) 1605.364331579 PNF to VNF phy_id: 1 (t1/2/3/4: 1506000, 1506001, 1506003, 1506124) txrx: 124 procT: 2 latency(us): 61(avg: 33) offset(us): -60 filtered(us): -60 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:2000 old_sfn/sf:2000 proc[rx:1999] [NFAPI_VNF] ( 201/8) 1605.876319164 PNF to VNF phy_id: 1 (t1/2/3/4: 2018001, 2017972, 2017982, 2018113) txrx: 112 procT: 10 latency(us): 51(avg: 33) offset(us): -80 filtered(us): -63 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-446 phy->previous_sf_offset_filtered:-446 phy->sf_offset_trend:549 [NFAPI_VNF] ( 253/0) 1606.388387650 PNF to VNF phy_id: 1 (t1/2/3/4: 2530001, 2530013, 2530015, 2530181) txrx: 180 procT: 2 latency(us): 89(avg: 33) offset(us): -77 filtered(us): -77 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:3000 old_sfn/sf:3000 proc[rx:2999] [NFAPI_VNF] ( 304/2) 1606.900444034 PNF to VNF phy_id: 1 (t1/2/3/4: 3042000, 3042105, 3042106, 3042237) txrx: 237 procT: 1 latency(us): 118(avg: 33) offset(us): -13 filtered(us): -69 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-63 phy->previous_sf_offset_filtered:-63 phy->sf_offset_trend:549 [NFAPI_VNF] ( 355/4) 1607.412367415 PNF to VNF phy_id: 1 (t1/2/3/4: 3554001, 3554020, 3554023, 3554162) txrx: 161 procT: 3 latency(us): 79(avg: 33) offset(us): -60 filtered(us): -60 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:4000 old_sfn/sf:4000 proc[rx:3999] [NFAPI_VNF] ( 406/6) 1607.924343896 PNF to VNF phy_id: 1 (t1/2/3/4: 4066001, 4065997, 4066011, 4066138) txrx: 137 procT: 14 latency(us): 61(avg: 33) offset(us): -65 filtered(us): -61 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-69 phy->previous_sf_offset_filtered:-69 phy->sf_offset_trend:66 [NFAPI_VNF] ( 457/8) 1608.436361177 PNF to VNF phy_id: 1 (t1/2/3/4: 4578001, 4577968, 4578011, 4578155) txrx: 154 procT: 43 latency(us): 55(avg: 33) offset(us): -88 filtered(us): -88 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:5000 old_sfn/sf:5000 proc[rx:4999] [NFAPI_VNF] ( 509/0) 1608.948340556 PNF to VNF phy_id: 1 (t1/2/3/4: 5090001, 5089994, 5089998, 5090135) txrx: 134 procT: 4 latency(us): 65(avg: 33) offset(us): -72 filtered(us): -86 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-61 phy->previous_sf_offset_filtered:-61 phy->sf_offset_trend:66 [RIC_AGENT] ranid 0 connecting to RIC at 192.168.200.11:36401 with IP 192.168.200.22 [SCTP] sctp_bindx SCTP_BINDX_ADD_ADDR socket bound to : 192.168.200.22 [SCTP] Converted ipv4 address 192.168.200.11 to network type [SCTP] connectx assoc_id 40 in progress..., used 1 addresses [SCTP] Inserted new descriptor for sd 92 in list, nb elements 2, assoc_id 40 [SCTP] Found data for descriptor 92 [SCTP] Received notification for sd 92, type 32769 [SCTP] Client association changed: 0 [SCTP] ---------------------- [SCTP] Peer addresses: [SCTP] - [192.168.200.11] [SCTP] ---------------------- [SCTP] ---------------------- [SCTP] SCTP Status: [SCTP] assoc id .....: 40 [SCTP] state ........: 4 [SCTP] instrms ......: 1 [SCTP] outstrms .....: 1 [SCTP] fragmentation : 65484 [SCTP] pending data .: 0 [SCTP] unack data ...: 0 [SCTP] rwnd .........: 106496 [SCTP] peer info : [SCTP] state ....: 2 [SCTP] cwnd .....: 131064 [SCTP] srtt .....: 0 [SCTP] rto ......: 3000 [SCTP] mtu ......: 65532 [SCTP] ---------------------- [SCTP] Comm up notified for sd 92, assigned assoc_id 40 [SCTP] Found data for descriptor 92 [SCTP] Received notification for sd 92, type 32776 [RIC_AGENT] new sctp assoc resp 40, sctp_state 2 for nb 0 [RIC_AGENT] new sctp assoc resp 40 for nb 0 1 3 02 F8 10 00000000111000000000 10 8 1 20 C0 4F 52 41 4E 2D 45 32 53 4D 2D 52 53 4D 00 00 1A 31 2E 33 2E 36 2E 31 2E 34 2E 31 2E 35 33 31 34 38 2E 31 2E 31 2E 32 2E 31 30 32 05 00 52 41 4E 20 53 6C 69 63 69 6E 67 01 00 01 00 04 00 04 00 01 04 30 04 43 1 1.3.6.1.4.1.53148.1.1.2.102 50 51 200 31 30 30 32 30 30 [RIC_AGENT] Send SCTP data, ranid:0, assoc_id:40, len:158 [SCTP] Successfully sent 158 bytes on stream 0 for assoc_id 40 [SCTP] Found data for descriptor 92 [SCTP] Received notification for sd 92, type 32777 [SCTP] Found data for descriptor 92 [SCTP] Received data from peer with unsollicited PPID 0, expecting 70 [SCTP] [40][92] Msg of length 64 received from port 36401, on stream 0, PPID 0 1 49 0 4 02 F8 10 11011110101111001010 52 53 S1-component 9 6 1 1 [RIC_AGENT] decoded successful outcome E2SetupResponse (1) [RIC_AGENT] Received E2SetupResponse (ranid 0) [RIC_AGENT] E2SetupResponse (ranid 0) from RIC (mcc=208,mnc=1,id=0) [SCTP] Found data for descriptor 92 [SCTP] Received data from peer with unsollicited PPID 0, expecting 70 [SCTP] [40][92] Msg of length 31 received from port 36401, on stream 0, PPID 0 11 C0 A8 54 16 49 5 44 43 11000000101010000101010000010110 1000111001000101 [RIC_AGENT] decoded initiating E2ConnectionUpdate (11) [RIC_AGENT] Received E2ConnectionUpdate from ranid 0 [RIC_AGENT] [e2ap_handle_e2_connection_update] Transaction ID:5[RIC_AGENT] Iter:0 [RIC_AGENT] [e2ap_handle_e2_connection_update] Received E2ConnectionUpdate Item within List [RIC_AGENT] [e2ap_handle_e2_connection_update] Preparing E2connectionUpdateAcknowledge 11 49 5 39 43 11000000101010000101010000010110 1000111001000101 40 41 11000000101010000101010000010110 1000111001000101 [RIC_AGENT] [e2ap_handle_e2_connection_update] Setting up New SCTP for Data Connection [RIC_AGENT] TNLAddress:3232257046 Port:36421 Remote Ipv4 Address:192.168.84.22 [RIC_AGENT] [e2ap_handle_e2_connection_update] ranid 0 Requesting data connection to RIC at 192.168.84.22:36421 with IP 192.168.200.22 [RIC_AGENT] Send SCTP data, ranid:0, assoc_id:40, len:49 [SCTP] sctp_bindx SCTP_BINDX_ADD_ADDR socket bound to : 192.168.200.22 [SCTP] Converted ipv4 address 192.168.84.22 to network type [SCTP] connectx assoc_id 42 in progress..., used 1 addresses [SCTP] Inserted new descriptor for sd 93 in list, nb elements 3, assoc_id 42 [SCTP] Found data for descriptor 93 [SCTP] Received notification for sd 93, type 32769 [SCTP] Client association changed: 0 [SCTP] ---------------------- [SCTP] Peer addresses: [SCTP] - [192.168.84.22] [SCTP] ---------------------- [SCTP] ---------------------- [SCTP] SCTP Status: [SCTP] assoc id .....: 42 [SCTP] state ........: 4 [SCTP] instrms ......: 1 [SCTP] outstrms .....: 1 [SCTP] fragmentation : 1432 [SCTP] pending data .: 0 [SCTP] unack data ...: 0 [SCTP] rwnd .........: 106496 [SCTP] peer info : [SCTP] state ....: 2 [SCTP] cwnd .....: 4380 [SCTP] srtt .....: 0 [SCTP] rto ......: 3000 [SCTP] mtu ......: 1480 [SCTP] ---------------------- [SCTP] Comm up notified for sd 93, assigned assoc_id 42 [RIC_AGENT] new sctp assoc resp 42, sctp_state 2 for nb 0 [RIC_AGENT] new sctp assoc resp 42 for nb 0 [RIC_AGENT] Data Connection Assoc Id:42 updated [RIC_AGENT] e2ap_generate_e2_config_update 10 [SCTP] Successfully sent 49 bytes on stream 0 for assoc_id 40 [SCTP] Found data for descriptor 93 [SCTP] Received notification for sd 93, type 32776 49 10 3 02 F8 10 00000000111000000000 33 34 200 31 30 30 32 30 30 [RIC_AGENT] Send SCTP data, ranid:0, assoc_id:42, len:47 [SCTP] Successfully sent 47 bytes on stream 0 for assoc_id 42 [SCTP] Found data for descriptor 93 [SCTP] Received notification for sd 93, type 32777 [SCTP] Found data for descriptor 93 [SCTP] Received data from peer with unsollicited PPID 0, expecting 70 [SCTP] [42][93] Msg of length 13 received from port 36421, on stream 0, PPID 0 10 49 10 [RIC_AGENT] decoded successful outcome E2nodeConfigurationUpdateAcknowledge (10) [SCTP] Found data for descriptor 92 [SCTP] Received notification for sd 92, type 32777 [NFAPI_VNF] ( 560/2) 1609.460382335 PNF to VNF phy_id: 1 (t1/2/3/4: 5602001, 5602030, 5602033, 5602177) txrx: 176 procT: 3 latency(us): 86(avg: 33) offset(us): -57 filtered(us): -57 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:6000 old_sfn/sf:6000 proc[rx:5999] [NFAPI_VNF] ( 611/4) 1609.972325511 PNF to VNF phy_id: 1 (t1/2/3/4: 6114001, 6113966, 6113969, 6114121) txrx: 120 procT: 3 latency(us): 58(avg: 33) offset(us): -93 filtered(us): -62 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-86 phy->previous_sf_offset_filtered:-86 phy->sf_offset_trend:73 [NFAPI_VNF] ( 662/6) 1610.484303488 PNF to VNF phy_id: 1 (t1/2/3/4: 6626001, 6625952, 6625954, 6626098) txrx: 97 procT: 2 latency(us): 47(avg: 33) offset(us): -96 filtered(us): -96 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:7000 old_sfn/sf:7000 proc[rx:6999] [NFAPI_VNF] ( 713/8) 1610.996913470 PNF to VNF phy_id: 1 (t1/2/3/4: 7138001, 7138564, 7138567, 7138708) txrx: 707 procT: 3 latency(us): 352(avg: 33) offset(us): 211 filtered(us): -58 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-62 phy->previous_sf_offset_filtered:-62 phy->sf_offset_trend:73 [NFAPI_VNF] ( 765/0) 1611.508317338 PNF to VNF phy_id: 1 (t1/2/3/4: 7650000, 7649975, 7649978, 7650111) txrx: 111 procT: 3 latency(us): 54(avg: 33) offset(us): -79 filtered(us): -79 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:8000 old_sfn/sf:8000 proc[rx:7999] [NFAPI_VNF] ( 816/2) 1612.20314311 PNF to VNF phy_id: 1 (t1/2/3/4: 8162001, 8161974, 8161977, 8162109) txrx: 108 procT: 3 latency(us): 52(avg: 33) offset(us): -79 filtered(us): -79 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-58 phy->previous_sf_offset_filtered:-58 phy->sf_offset_trend:73 [NFAPI_VNF] ( 867/4) 1612.532325484 PNF to VNF phy_id: 1 (t1/2/3/4: 8674001, 8673974, 8673978, 8674120) txrx: 119 procT: 4 latency(us): 57(avg: 33) offset(us): -84 filtered(us): -84 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:9000 old_sfn/sf:9000 proc[rx:8999] [NFAPI_VNF] ( 918/6) 1613.44326255 PNF to VNF phy_id: 1 (t1/2/3/4: 9186000, 9185993, 9185995, 9186120) txrx: 120 procT: 2 latency(us): 59(avg: 33) offset(us): -66 filtered(us): -82 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-79 phy->previous_sf_offset_filtered:-79 phy->sf_offset_trend:68 [NFAPI_VNF] ( 969/8) 1613.556310326 PNF to VNF phy_id: 1 (t1/2/3/4: 9698000, 9697969, 9697971, 9698105) txrx: 105 procT: 2 latency(us): 51(avg: 33) offset(us): -82 filtered(us): -82 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:10000 old_sfn/sf:10000 proc[rx:9999] [NFAPI_VNF] (1021/0) 1614.68594698 PNF to VNF phy_id: 1 (t1/2/3/4:10210001, 10210251, 10210255, 10210204) txrx: 203 procT: 4 latency(us): 99(avg: 33) offset(us): 151 filtered(us): -53 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-82 phy->previous_sf_offset_filtered:-82 phy->sf_offset_trend:80 [PHY] [eNB] sfn/sf:00 old_sfn/sf:00 proc[rx:10239] [NFAPI_VNF] ( 48/2) 1614.580316164 PNF to VNF phy_id: 1 (t1/2/3/4: 482001, 481975, 481977, 482111) txrx: 110 procT: 2 latency(us): 54(avg: 33) offset(us): -80 filtered(us): -80 wrap[t1:0 t2:0] [NFAPI_VNF] ( 99/4) 1615.92338531 PNF to VNF phy_id: 1 (t1/2/3/4: 994001, 993993, 993997, 994133) txrx: 132 procT: 4 latency(us): 64(avg: 33) offset(us): -72 filtered(us): -79 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-53 phy->previous_sf_offset_filtered:-53 phy->sf_offset_trend:80 [PHY] [eNB] sfn/sf:1000 old_sfn/sf:1000 proc[rx:999] [NFAPI_VNF] ( 150/6) 1615.604313698 PNF to VNF phy_id: 1 (t1/2/3/4: 1506001, 1505982, 1505985, 1506108) txrx: 107 procT: 3 latency(us): 52(avg: 33) offset(us): -71 filtered(us): -71 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:2000 old_sfn/sf:2000 proc[rx:1999] [NFAPI_VNF] ( 201/8) 1616.116311263 PNF to VNF phy_id: 1 (t1/2/3/4: 2018001, 2017943, 2017945, 2018106) txrx: 105 procT: 2 latency(us): 51(avg: 33) offset(us): -109 filtered(us): -76 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-79 phy->previous_sf_offset_filtered:-79 phy->sf_offset_trend:66 [NFAPI_VNF] ( 253/0) 1616.628316728 PNF to VNF phy_id: 1 (t1/2/3/4: 2530001, 2529977, 2529979, 2530112) txrx: 111 procT: 2 latency(us): 54(avg: 33) offset(us): -78 filtered(us): -78 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:3000 old_sfn/sf:3000 proc[rx:2999] [NFAPI_VNF] ( 304/2) 1617.140531594 PNF to VNF phy_id: 1 (t1/2/3/4: 3042001, 3042189, 3042192, 3042327) txrx: 326 procT: 3 latency(us): 161(avg: 33) offset(us): 27 filtered(us): -65 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-76 phy->previous_sf_offset_filtered:-76 phy->sf_offset_trend:66 [NFAPI_VNF] ( 355/4) 1617.652321554 PNF to VNF phy_id: 1 (t1/2/3/4: 3554000, 3553981, 3553984, 3554115) txrx: 115 procT: 3 latency(us): 56(avg: 33) offset(us): -75 filtered(us): -75 wrap[t1:0 t2:0] [PHY] [eNB] sfn/sf:4000 old_sfn/sf:4000 proc[rx:3999] [NFAPI_VNF] ( 406/6) 1618.164317915 PNF to VNF phy_id: 1 (t1/2/3/4: 4066001, 4065977, 4065980, 4066113) txrx: 112 procT: 3 latency(us): 54(avg: 33) offset(us): -78 filtered(us): -76 wrap[t1:0 t2:0] [NFAPI_VNF] PNF to VNF phy_id:1 adjustment0 phy->previous_sf_offset_filtered:-65 phy->previous_sf_offset_filtered:-65 phy->sf_offset_trend:66 [NFAPI_VNF] ( 457/8) 1618.676312276 PNF to VNF phy_id: 1 (t1/2/3/4: 4578001, 4577966, 4577969, 4578107) txrx: 106 procT: 3 latency(us): 51(avg: 33) offset(us): -86 filtered(us): -86 wrap[t1:0 t2:0] [PHY] [eNB] ERROR pthread_mutex_lock for eNB RXTX thread 1 (IC 0) /root/nfapi/oai_integration/nfapi_vnf.c:338 wake_eNB_rxtx() Exiting OAI softmodem: error locking mutex_rxtx riab oai-enb-du-0 1/1 Running 4 10m Pod going to Crashloopback off frequently and coming back up.