5g NSA - RLF immediately after NR attach

[gaurishdotkdm]

trafficstars

Issue Description

srsue -> rrcConnectionReconfigurationComplete transmitted by UE did not reach eNB, SNR kept dropping, followed by out-of-sync
srenb -> RLC RLF timer for rnti=0x46 expired after 4000 ms

Setup Details

2 x RF-frontends - USRP X300
2 x PCs with a Linux based OS and identical configuration (below) - srsRAN installed on both PCs
Operating System: Ubuntu 20.04.3 LTS
Kernel: Linux 5.4.0-99-generic
Architecture: x86-64

On machine 1, in one console, run srsEPC - in another console, run srsENB
On machine 2, run srsUE

RF front-end driver: 3.15.0

Expected Behavior

srsUE on (PC2/ USRP2) should attach to the (srsENB/GNB + srsEPC) radiated from (PC1/ USRP1)

Actual Behaviour

-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=

                                       stdout print below

------------------------- srsenb ----------------------------

Opening 2 channels in RF device=default with args=default
Available RF device list: UHD 
Trying to open RF device 'UHD'
Opening USRP channels=2, args: type=x300,master_clock_rate=184.32e6
-- X300 initialization sequence...
-- Determining maximum frame size... 8000 bytes.
-- Setup basic communication...
-- Loading values from EEPROM...
-- Setup RF frontend clocking...
-- Radio 1x clock:184.32
-- Initialize Radio0 control...
-- Performing register loopback test... pass
-- Initialize Radio1 control...
-- Performing register loopback test... pass
--     1) catch time transition at pps edge
--     2) set times next pps (synchronously)
RF device 'UHD' successfully opened

==== eNodeB started ===
Type <t> to view trace
Setting frequency: DL=1945.0 Mhz, UL=1865.0 MHz for cc_idx=0 nof_prb=25
Setting frequency: DL=1970.0 Mhz, UL=1890.0 MHz for cc_idx=1 nof_prb=25
RACH:  tti=661, cc=0, preamble=9, offset=5, temp_crnti=0x46
RACH:  tti=661, cc=0, preamble=18, offset=21, temp_crnti=0x47
Disconnecting rnti=0x47.
User 0x46 connected
RACH:  slot=1451, cc=0, preamble=0, offset=0, temp_crnti=0x4602
RACH:  slot=1491, cc=0, preamble=0, offset=71, temp_crnti=0x4603
Disconnecting rnti=0x4602.
Disconnecting rnti=0x4603.
Disconnecting rnti=0x46.
Disconnecting rnti=0x4601.
^CStopping ..
---  exiting  ---
root@lab-server-2:~# srsenb

------------------------- srsepc ----------------------------

UL NAS: Received ESM Information Response
ESM Info: APN srsapn
Getting subscription information -- QCI 7
Sending Create Session Request.
Creating Session Response -- IMSI: 1010123456789
Creating Session Response -- MME control TEID: 1
Received GTP-C PDU. Message type: GTPC_MSG_TYPE_CREATE_SESSION_REQUEST
SPGW: Allocated Ctrl TEID 1
SPGW: Allocated User TEID 1
SPGW: Allocate UE IP 172.16.0.2
Received Create Session Response
Create Session Response -- SPGW control TEID 1
Create Session Response -- SPGW S1-U Address: 127.0.1.100
SPGW Allocated IP 172.16.0.2 to IMSI 001010123456789
Adding attach accept to Initial Context Setup Request
Sent Initial Context Setup Request. E-RAB id 5 
Received Initial Context Setup Response
E-RAB Context Setup. E-RAB id 5
E-RAB Context -- eNB TEID 0x1; eNB GTP-U Address 127.0.1.1
UL NAS: Received Attach Complete
Unpacked Attached Complete Message. IMSI 1010123456789
Unpacked Activate Default EPS Bearer message. EPS Bearer id 5
Received GTP-C PDU. Message type: GTPC_MSG_TYPE_MODIFY_BEARER_REQUEST
Sending EMM Information
Received UE Context Release Request. MME-UE S1AP Id 1
There are active E-RABs, send release access bearers request
Received GTP-C PDU. Message type: GTPC_MSG_TYPE_RELEASE_ACCESS_BEARERS_REQUEST
Received UE Context Release Complete. MME-UE S1AP Id 1
UE Context Release Completed.
SCTP Association Shutdown. Association: 222
Deleting eNB context. eNB Id: 0x19b
Releasing UEs context
No UEs to be released
^CStopping ..
Deleting UE EMM context. IMSI: 001010123456789
Deleting SP-GW GTP-C Tunnel. IMSI: 001010123456789

---  exiting  ---
root@lab-server-2:~# srsepc

------------------------- srsue ----------------------------

Opening 2 channels in RF device=default with args=default
Available RF device list: UHD 
Trying to open RF device 'UHD'
Opening USRP channels=2, args: type=x300,master_clock_rate=184.32e6
-- X300 initialization sequence...
-- Determining maximum frame size... 8000 bytes.
-- Setup basic communication...
-- Loading values from EEPROM...
-- Setup RF frontend clocking...
-- Radio 1x clock:184.32
-- Initialize Radio0 control...
-- Performing register loopback test... pass
-- Initialize Radio1 control...
-- Performing register loopback test... pass
--     1) catch time transition at pps edge
--     2) set times next pps (synchronously)
RF device 'UHD' successfully opened
Waiting PHY to initialize ... done!
Attaching UE...
.
Found Cell:  Mode=FDD, PCI=1, PRB=25, Ports=1, CP=Normal, CFO=7.0 KHz
Found PLMN:  Id=00101, TAC=7
Random Access Transmission: seq=9, tti=661, ra-rnti=0x2
RRC Connected
Random Access Complete.     c-rnti=0x46, ta=5
Network attach successful. IP: 172.16.0.2
Software Radio Systems RAN (srsRAN) 18/2/2022 1:34:52 TZ:0
RRC NR reconfiguration successful.
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0xf, tti=1451
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0xf, tti=1491
RF status: O=0, U=1, L=0
^CStopping ..
Couldn't stop after 5s. Forcing exit.
Killed
root@lab-server-4:~# srsue

---

                                            **LOG SNIPPET**

------------------------------------------ enb.log ----------------------------------------

2022-02-18T01:34:52.565599 [RRC    ] [I] Tx SRB1 PDU, rnti=0x46 - rrcConnectionReconfiguration (139 B)
                    "measIdToAddModList": [
                      {
                        "measId": 1,
                        "measObjectId": 2,
                        "reportConfigId": 1
                      }
                      
2022-02-18T01:34:52.605151 [RRC    ] [I] Rx SRB1 PDU, rnti=0x46 - rrcConnectionReconfigurationComplete (2 B)

2022-02-18T01:34:52.965153 [RRC    ] [I] Rx SRB1 PDU, rnti=0x46 - measurementReport (11 B)
                    "measId": 1,
                      "measResultNeighCellListNR-r15": [
                        {
                          "pci-r15": 500,
                          "measResultCell-r15": {
                            "rsrpResult-r15": 96,
                            "rsrqResult-r15": 54,
                            "rs-sinr-Result-r15": 94
                                                
2022-02-18T01:34:52.965176 [RRC    ] [I] Triggering SgNB addition for E-UTRA rnti=0x46

2022-02-18T01:34:52.965584 [RLC-NR ] [I] Added LTE radio bearer with LCID 0 in Transparent Mode
2022-02-18T01:34:52.965596 [RLC-NR ] [I] Added NR radio bearer with LCID 4 in Unacknowledged Mode

2022-02-18T01:34:52.965702 [RRC    ] [D] RRC state 8
2022-02-18T01:34:52.965702 [RRC    ] [I] UE doesn't support CA. Skipping SCell activation

2022-02-18T01:34:52.965730 [RLC    ] [I] Deleted RLC bearer with LCID 3
2022-02-18T01:34:52.965731 [STCK   ] [I] Bearers: Removed mapping for EPS bearer ID 5 for rnti=0x46

2022-02-18T01:34:52.965747 [RRC    ] [I] Tx SRB1 PDU, rnti=0x46 - rrcConnectionReconfiguration (277 B) ////received at UE
                    "measIdToRemoveList": [
                      1
                    ]

////RRC reconfig complete is missing here

2022-02-18T01:34:53.090285 [RRC-NR ] [I] Activity timer for rnti=0x4602 expired after 100 ms
2022-02-18T01:34:53.090296 [MAC    ] [I] [ 1550] SCHED: discarding DL TB=0 pid=0, tti=1546, maximum number of retx exceeded (4)

2022-02-18T01:34:57.148073 [RRC    ] [I] RLC RLF timer for rnti=0x46 expired after 4000 ms

2022-02-18T01:34:57.149202 [RRC    ] [I] Tx SRB1 PDU, rnti=0x46 - rrcConnectionRelease (2 B)

------------------------------------------ ue.log ----------------------------------------

2022-02-18T01:34:52.572265 [RLC    ] [I] Added LTE radio bearer with LCID 2 in Acknowledged Mode
2022-02-18T01:34:52.572267 [RRC    ] [I] Added radio bearer SRB2
2022-02-18T01:34:52.572273 [RLC    ] [I] Added LTE radio bearer with LCID 3 in Unacknowledged Mode
2022-02-18T01:34:52.572285 [RRC    ] [I] MEAS (NR R15):  Added objectId=2, carrier_freq=394090, 0 black-listed cells
2022-02-18T01:34:52.572288 [RRC    ] [I] MEAS: Inter RAT Added reportConfig id=1, event-type=eventB1-NR-r15, time-to-trigger=100 ms, reportInterval=120
2022-02-18T01:34:52.572288 [RRC    ] [D] MEAS:   B1-NR-R15-threashold (56)=-100.0 dBm
2022-02-18T01:34:52.572289 [RRC    ] [I] MEAS:  AddMod measId=1, measObjectId=2, reportConfigId=1
2022-02-18T01:34:52.572295 [PHY    ] [I] [ 1030] INTRA-LTE-750: Disabled neighbour cell search
2022-02-18T01:34:52.572296 [RRC-NR ] [D] Measuring phy cell 394090 

2022-02-18T01:34:52.572312 [RRC    ] [D] SRB1 - Tx rrcConnectionReconfigurationComplete (2 B)
              "rrcConnectionReconfigurationComplete-r8": {

2022-02-18T01:34:52.572394 [NAS    ] [I] Received Attach Accept
2022-02-18T01:34:52.572399 [NAS    ] [I] Network attach successful. APN: srsapn, IP: 172.16.0.2
2022-02-18T01:34:52.574566 [NAS    ] [I] Sending Attach Complete
2022-02-18T01:34:52.574592 [RRC    ] [D] SRB2 - Tx ulInformationTransfer (16 B)

2022-02-18T01:34:52.921988 [RRC    ] [I] MEAS:  Generate report MeasId=1, Pcell rsrp=-43.799377 rsrq=-3.531565

2022-02-18T01:34:52.922009 [RRC    ] [D] SRB1 - Tx measurementReport (11 B) ////received at eNB
                    "measId": 1,
                    "measResultPCell": {
                      "rsrpResult": 97,
                      "rsrqResult": 32
                    },
                    "measResultNeighCells": {
                      "measResultNeighCellListNR-r15": [
                        {
                          "pci-r15": 500,
                          "measResultCell-r15": {
                            "rsrpResult-r15": 96,
                            "rsrqResult-r15": 54,
                            "rs-sinr-Result-r15": 94
                            
2022-02-18T01:34:52.971956 [RRC    ] [D] SRB1 - Rx rrcConnectionReconfiguration (277 B) ////received at UE
                    "measIdToRemoveList": [
                      1
                      
2022-02-18T01:34:52.972075 [RRC-NR ] [D] RRC NR Reconfiguration - Rx NR Secondary Cell Group Cfg R15 (246 B)
        "physCellId": 500,
          "frequencyInfoDL": {
            "absoluteFrequencySSB": 394090,
            "frequencyBandList": [
              2
            ],
            "absoluteFrequencyPointA": 393568,
            "scs-SpecificCarrierList": [
              {
                "offsetToCarrier": 0,
                "subcarrierSpacing": "kHz15",
                "carrierBandwidth": 25

                        
2022-02-18T01:34:52.976073 [RRC-NR ] [I] Proc "NR Connection Reconfiguration" - Finished NR Connection Reconfiguration successfully
2022-02-18T01:34:52.976104 [RRC    ] [D] SRB1 - Tx rrcConnectionReconfigurationComplete (5 B)
                            "scg-ConfigResponseNR-r15": "00"

2022-02-18T01:34:52.976123 [RRC    ] [D] SRB1 - Tx rrcConnectionReconfigurationComplete (2 B)
              "rrcConnectionReconfigurationComplete-r8": {

2022-02-18T01:34:52.976154 [MAC    ] [D] [ 1431] BSR:   New data available for lcid=1
2022-02-18T01:34:52.976155 [MAC    ] [D] [ 1431] BSR:   Triggering SR procedure

2022-02-18T01:34:52.976691 [PHY    ] [D] [ 1435] SNR=32.6 dB, RSRP=-44.5 dBm sync=in-sync from channel estimator

2022-02-18T01:34:52.977637 [PHY1   ] [D] [ 1436] set_uci_sr() sending SR: sr_enabled=true, last_tx_tti=1440
2022-02-18T01:34:52.979596 [RRC-NR ] [I] PHY configuration completed. Starting RA procedure.

2022-02-18T01:34:52.982922 [PHY    ] [D] [ 1441] SNR=32.8 dB, RSRP=-44.5 dBm sync=in-sync from channel estimator
2022-02-18T01:34:52.998812 [PHY    ] [D] [ 1457] SNR=29.9 dB, RSRP=-47.7 dBm sync=in-sync from channel estimator
2022-02-18T01:34:53.003642 [PHY    ] [D] [ 1462] SNR=18.2 dB, RSRP=-48.3 dBm sync=in-sync from channel estimator
2022-02-18T01:34:53.012015 [PHY    ] [D] [ 1470] SNR=8.4 dB, RSRP=-48.4 dBm sync=in-sync from channel estimator
	
2022-02-18T01:34:53.024892 [PHY    ] [I] [ 1483] Out-of-sync 0/20
2022-02-18T01:34:53.047738 [PHY    ] [W] [ 1506] SYNC:  Out-of-sync detected in PSS/SSS

2022-02-18T01:35:07.453908 [NAS    ] [I] Switching off

---

Attachment

issue_813_conf_files.zip issue_813_log_files.zip