srsRAN_4G
srsRAN_4G copied to clipboard
srsran
RRCConnectionSetupComplete - Scheduling Request Failed
## Issue Description ## srsue complains - immediately after Random Access Complete - "Scheduling request failed: releasing RRC connection". srenb prints "Could not transmit RAR within the window (RA=2261, Window=[2264, 2274), RAR=2274"
## 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 + srsEPC) radiated from (PC1/ USRP1)
## Actual Behaviour ##
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= ENB ==> -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
-- screen display after executing command "srsenb"
==== eNodeB started ===
Type <t> to view trace
Setting frequency: DL=1930.0 Mhz, UL=1850.0 MHz for cc_idx=0 nof_prb=50
RACH: tti=2261, cc=0, preamble=17, offset=1, temp_crnti=0x46
RACH: tti=2261, cc=0, preamble=18, offset=23, temp_crnti=0x47
SCHED: Could not transmit RAR within the window (RA=2261, Window=[2264, 2274), RAR=2274
Disconnecting rnti=0x47.
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
-- enb.log
2022-02-09T22:31:31.970238 [PHY ] [I] [ 2262] PRACH: cc=0, 0/2, preamble=17, offset=1.0 us, peak2avg=154.5, max_offset=30.0 us
2022-02-09T22:31:31.970241 [PHY ] [I] [ 2262] PRACH: cc=0, 1/2, preamble=18, offset=12.4 us, peak2avg=264.9, max_offset=30.0 us
2022-02-09T22:31:31.970423 [MAC ] [I] [ 2261] SCHED: New PRACH tti=2261, preamble=17, temp_crnti=0x46, ta_cmd=1, msg3_size=7
2022-02-09T22:31:31.970423 [MAC ] [I] [ 2261] RACH: tti=2261, cc=0, preamble=17, offset=1, temp_crnti=0x46
2022-02-09T22:31:31.971252 [MAC ] [I] [ 2262] SCHED: RAR, ra-rnti=2, rbgs=[0, 1), dci=(2,0), msg3 grants=[{c-rnti=0x46, rba=102, mcs=0}]
2022-02-09T22:31:31.979082 [MAC ] [I] [ 2269] SCHED: New PRACH tti=2261, preamble=18, temp_crnti=0x47, ta_cmd=23, msg3_size=7
2022-02-09T22:31:31.979083 [MAC ] [I] [ 2269] RACH: tti=2261, cc=0, preamble=18, offset=23, temp_crnti=0x47
2022-02-09T22:31:31.979244 [MAC ] [W] [ 2270] SCHED: Could not transmit RAR within the window (RA=2261, Window=[2264, 2274), RAR=2274
2022-02-09T22:31:32.006248 [RRC ] [I] Rx SRB0 PDU, rnti=0x46 - rrcConnectionRequest (6 B)
2022-02-09T22:31:32.006492 [RRC ] [I] Tx SRB0 PDU, rnti=0x46 - rrcConnectionSetup (20 B)
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
UE ==>
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -- screen display after executing command "srsue"
Attaching UE...
.
Found Cell: Mode=FDD, PCI=1, PRB=50, Ports=1, CP=Normal, CFO=0.6 KHz
Found PLMN: Id=00101, TAC=7
Random Access Transmission: seq=17, tti=2261, ra-rnti=0x2
RRC Connected
Random Access Complete. c-rnti=0x46, ta=1
Scheduling request failed: releasing RRC connection...
Random Access Transmission: seq=20, tti=3601, ra-rnti=0x2
Random Access Transmission: seq=32, tti=3651, ra-rnti=0x2
Random Access Transmission: seq=13, tti=3701, ra-rnti=0x2
Random Access Transmission: seq=28, tti=3751, ra-rnti=0x2
Random Access Complete. c-rnti=0x46, ta=1
Random Access Transmission: seq=8, tti=3851, ra-rnti=0x2
Random Access Complete. c-rnti=0x46, ta=1
Random Access Transmission: seq=31, tti=3971, ra-rnti=0x2
Random Access Complete. c-rnti=0x46, ta=1
Random Access Transmission: seq=19, tti=4041, ra-rnti=0x2
Random Access Complete. c-rnti=0x46, ta=1
Warning: Detected Radio-Link Failure
Random Access Transmission: seq=41, tti=4101, ra-rnti=0x2
Random Access Complete. c-rnti=0x46, ta=27
RRC IDLE
Attach failed (attempt 1/5)
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -- ue.log
022-02-09T22:31:31.601818 [NAS ] [D] Attempting to select PLMN
2022-02-09T22:31:31.601819 [STCK ] [D] tti_tprof: duration=0 msec
2022-02-09T22:31:31.601878 [PHY ] [I] [ 0] SYNC: MIB Decoded: Mode=FDD, PCI=1, PRB=50, Ports=1, CFO=0.6 KHz
2022-02-09T22:31:31.601897 [PHY ] [D] [ 0] SYNC: state=SEARCH, tti=6
2022-02-09T22:31:31.601897 [PHY ] [D] [ 0] Discarding 1920 samples
2022-02-09T22:31:31.601899 [PHY ] [I] [ 0] Cell Search: Found cell with PCI=1 with 50 PRB
2022-02-09T22:31:31.601899 [PHY ] [I] [ 0] Cell Search: No more frequencies in the current EARFCN set
2022-02-09T22:31:31.601927 [RRC ] [I] FSM "phy_controller" - PHY cell search completed. Found cell {pci=1, dl_earfcn=600}
2022-02-09T22:31:31.601931 [RRC ] [I] FSM "phy_controller" - transition detected - searching_cell -> unknown_st (cause: cell_srch_res)
2022-02-09T22:31:31.601933 [RRC ] [I] Proc "Cell Search" - Cell found in this frequency. Setting new serving cell EARFCN=600 PCI=1 ...
2022-02-09T22:31:31.601942 [RRC ] [I] Adding neighbour cell {cell_id: 0x0, pci: 1, dl_earfcn: 600, rsrp=+nan, cfo=+601.2}, nof_neighbours=1
2022-02-09T22:31:31.601944 [RRC ] [D] Neighbours: [{cell_id: 0x0, pci: 1, dl_earfcn: 600, rsrp=+nan, cfo=+601.2}]
2022-02-09T22:31:31.601945 [RRC ] [I] Setting serving cell {cell_id: 0x0, pci: 1, dl_earfcn: 600, rsrp=+nan, cfo=+601.2}, nof_neighbours=0
2022-02-09T22:31:31.601950 [RRC ] [I] FSM "phy_controller" - transition detected - unknown_st -> selecting_cell (cause: cell_sel_cmd)
2022-02-09T22:31:31.601950 [RRC ] [I] FSM "selecting_cell" - Starting for pci=1, earfcn=600
2022-02-09T22:31:31.601951 [PHY ] [I] [ 0] Cell Select: Going to IDLE
2022-02-09T22:31:31.601955 [RLC ] [I] BCCH BCH message received.
0000: 60 bc 00
2022-02-09T22:31:31.601959 [PHY ] [I] [ 0] Resetting PHY...
2022-02-09T22:31:31.601959 [PHY ] [I] [ 0] PHY: Set TA base: n_ta: 0, ta_usec: 0.0
2022-02-09T22:31:31.601966 [RRC ] [D] BCCH-BCH - Rx MIB (3 B)
0000: 60 bc 00
2022-02-09T22:31:31.601967 [RRC ] [D] Content:
[
{
"BCCH-BCH-Message": {
"message": {
"dl-Bandwidth": "n50",
"phich-Config": {
"phich-Duration": "normal",
"phich-Resource": "oneSixth"
},
"systemFrameNumber": "00101111",
"schedulingInfoSIB1-BR-r13": 0,
"systemInfoUnchanged-BR-r15": false,
"spare": "0000"
}
}
}
]
2022-02-09T22:31:31.767544 [PHY ] [I] [ 2056] Out-of-sync 17/20
2022-02-09T22:31:31.768586 [PHY ] [I] [ 2057] Out-of-sync 18/20
2022-02-09T22:31:31.770626 [PHY ] [D] [ 2059] SYNC: state=CAMPING, tti=2060
2022-02-09T22:31:31.771516 [PHY ] [D] [ 2060] SYNC: state=CAMPING, tti=2061
2022-02-09T22:31:31.796764 [RRC ] [D] BCCH-DLSCH - Rx systemInformationBlockType1 (18 B)
0000: 40 40 04 03 00 07 00 19 b0 18 14 10 10 82 80 00
0010: 00 00
2022-02-09T22:31:31.796829 [RRC ] [D] Content:
[
{
"BCCH-DL-SCH-Message": {
"message": {
"c1": {
"systemInformationBlockType1": {
"cellAccessRelatedInfo": {
"plmn-IdentityList": [
{
"plmn-Identity": {
"mcc": [
0,
0,
1
],
"mnc": [
0,
1
]
},
"cellReservedForOperatorUse": "notReserved"
}
],
"trackingAreaCode": "0000000000000111",
"cellIdentity": "0000000000011001101100000001",
"cellBarred": "notBarred",
"intraFreqReselection": "allowed",
"csg-Indication": false
},
"cellSelectionInfo": {
"q-RxLevMin": -65
},
"freqBandIndicator": 2,
"schedulingInfoList": [
{
"si-Periodicity": "rf16",
"sib-MappingInfo": [
"sibType3"
]
}
],
"si-WindowLength": "ms20",
"systemInfoValueTag": 0
}
}
}
}
}
]
2022-02-09T22:31:31.797694 [PHY ] [D] [ 2086] SNR=17.6 dB, RSRP=-31.7 dBm sync=in-sync from channel estimator
2022-02-09T22:31:31.797756 [RRC ] [I] Proc "Cell Search" - Completed successfully
2022-02-09T22:31:31.797758 [RRC ] [I] Proc "PLMN Search" - completed PLMN search
2022-02-09T22:31:31.797758 [RRC ] [I] Proc "PLMN Search" - completed with success
2022-02-09T22:31:31.797780 [NAS ] [D] Starting T3410. Timeout in 15000 ms.
2022-02-09T22:31:31.797780 [NAS ] [D] Initiating RRC Connection
2022-02-09T22:31:31.797781 [RRC ] [I] Proc "Connection Request" - Initiation of Connection establishment procedure
2022-02-09T22:31:31.797787 [RRC ] [I] Proc "Cell Selection" - Current serving cell: {cell_id: 0x19b01, pci: 1, dl_earfcn: 600, rsrp=-27.6, cfo=+293.8}
2022-02-09T22:31:31.854695 [PHY ] [D] [ 2143] SNR=39.3 dB, RSRP=-32.5 dBm sync=in-sync from channel estimator
2022-02-09T22:31:31.960772 [RRC ] [D] Content:
[
{
"BCCH-DL-SCH-Message": {
"message": {
"c1": {
"systemInformation": {
"criticalExtensions": {
"systemInformation-r8": {
"sib-TypeAndInfo": [
{
"sib2": {
"radioResourceConfigCommon": {
"rach-ConfigCommon": {
"preambleInfo": {
"numberOfRA-Preambles": "n52"
},
"powerRampingParameters": {
"powerRampingStep": "dB6",
"preambleInitialReceivedTargetPower": "dBm-104"
},
"ra-SupervisionInfo": {
"preambleTransMax": "n10",
"ra-ResponseWindowSize": "sf10",
"mac-ContentionResolutionTimer": "sf64"
},
"maxHARQ-Msg3Tx": 4
},
"bcch-Config": {
"modificationPeriodCoeff": "n16"
},
"pcch-Config": {
"defaultPagingCycle": "rf32",
"nB": "oneT"
},
"prach-Config": {
"rootSequenceIndex": 128,
"prach-ConfigInfo": {
"prach-ConfigIndex": 3,
"highSpeedFlag": false,
"zeroCorrelationZoneConfig": 5,
"prach-FreqOffset": 4
}
},
"pdsch-ConfigCommon": {
"referenceSignalPower": 0,
"p-b": 0
},
"pusch-ConfigCommon": {
"pusch-ConfigBasic": {
"n-SB": 1,
"hoppingMode": "interSubFrame",
"pusch-HoppingOffset": 2,
"enable64QAM": false
},
"ul-ReferenceSignalsPUSCH": {
"groupHoppingEnabled": false,
"groupAssignmentPUSCH": 0,
"sequenceHoppingEnabled": false,
"cyclicShift": 0
}
},
"pucch-ConfigCommon": {
"deltaPUCCH-Shift": "ds1",
"nRB-CQI": 1,
"nCS-AN": 0,
"n1PUCCH-AN": 12
},
"soundingRS-UL-ConfigCommon": {
},
"uplinkPowerControlCommon": {
"p0-NominalPUSCH": -85,
"alpha": "al07",
"p0-NominalPUCCH": -107,
"deltaFList-PUCCH": {
"deltaF-PUCCH-Format1": "deltaF0",
"deltaF-PUCCH-Format1b": "deltaF3",
"deltaF-PUCCH-Format2": "deltaF1",
"deltaF-PUCCH-Format2a": "deltaF2",
"deltaF-PUCCH-Format2b": "deltaF2"
},
"deltaPreambleMsg3": 6
},
"ul-CyclicPrefixLength": "len1"
},
"ue-TimersAndConstants": {
"t300": "ms2000",
"t301": "ms100",
"t310": "ms200",
"n310": "n1",
"t311": "ms10000",
"n311": "n1"
},
"freqInfo": {
"ul-CarrierFreq": 18600,
"ul-Bandwidth": "n50",
"additionalSpectrumEmission": 1
},
"timeAlignmentTimerCommon": "infinity"
}
},
{
"sib3": {
"cellReselectionInfoCommon": {
"q-Hyst": "dB2"
},
"cellReselectionServingFreqInfo": {
"s-NonIntraSearch": 3,
"threshServingLow": 2,
"cellReselectionPriority": 6
},
"intraFreqCellReselectionInfo": {
"q-RxLevMin": -61,
"p-Max": 23,
"s-IntraSearch": 5,
"presenceAntennaPort1": true,
"neighCellConfig": "01",
"t-ReselectionEUTRA": 1
}
}
}
]
}
}
}
}
}
}
}
]
2022-02-09T22:31:31.960772 [RRC ] [I] Processing SIB2 (0/2)
2022-02-09T22:31:31.960774 [RRC ] [I] SIB2 received
2022-02-09T22:31:31.960788 [PHY ] [D] [ 2249] Configuring PRACH parameters
2022-02-09T22:31:31.960789 [PHY ] [I] [ 2249] PRACH: [cell.id](http://cell.id/)=1, configIdx=3, rootSequence=128, zeroCorrelationConfig=5, freqOffset=4
2022-02-09T22:31:31.961051 [PHY ] [I] [ 2249] Finished setting new PRACH configuration.
2022-02-09T22:31:31.961610 [RRC ] [I] Proc "Cell Selection" - Completed with success.
2022-02-09T22:31:31.961628 [RRC ] [I] Set Constants and Timers: N310=1, N311=1, t300=2000, t301=100, t310=200, t311=10000
2022-02-09T22:31:31.961642 [RRC ] [D] SRB0 - Tx rrcConnectionRequest (6 B)
0000: 58 37 f1 13 d8 18
2022-02-09T22:31:31.961643 [RRC ] [D] Content:
[
{
"UL-CCCH-Message": {
"message": {
"c1": {
"rrcConnectionRequest": {
"criticalExtensions": {
"rrcConnectionRequest-r8": {
"ue-Identity": {
"randomValue": "1000001101111111000100010011110110000001"
},
"establishmentCause": "mo-Data",
"spare": "0"
}
}
}
}
}
}
}
]
2022-02-09T22:31:32.013841 [PHY ] [D] [ 2302] SNR=35.8 dB, RSRP=-32.6 dBm sync=in-sync from channel estimator
2022-02-09T22:31:32.013842 [RRC ] [D] SRB0 - Rx rrcConnectionSetup (20 B)
0000: 60 12 9b 2e 66 1e 82 f2 e0 cc c8 60 d3 00 00 99
0010: 02 00 03 e0
2022-02-09T22:31:32.013844 [RRC ] [D] Content:
[
{
"DL-CCCH-Message": {
"message": {
"c1": {
"rrcConnectionSetup": {
"rrc-TransactionIdentifier": 0,
"criticalExtensions": {
"c1": {
"rrcConnectionSetup-r8": {
"radioResourceConfigDedicated": {
"srb-ToAddModList": [
{
"srb-Identity": 1,
"rlc-Config": {
},
"logicalChannelConfig": {
}
}
],
"mac-MainConfig": {
"explicitValue": {
"ul-SCH-Config": {
"maxHARQ-Tx": "n4",
"periodicBSR-Timer": "sf20",
"retxBSR-Timer": "sf320",
"ttiBundling": false
},
"timeAlignmentTimerDedicated": "infinity",
"phr-Config": {
"setup": {
"periodicPHR-Timer": "sf50",
"prohibitPHR-Timer": "sf0",
"dl-PathlossChange": "dB3"
}
}
}
},
"physicalConfigDedicated": {
"pdsch-ConfigDedicated": {
"p-a": "dB0"
},
"pucch-ConfigDedicated": {
"ackNackRepetition": {
}
},
"pusch-ConfigDedicated": {
"betaOffset-ACK-Index": 6,
"betaOffset-RI-Index": 6,
"betaOffset-CQI-Index": 6
},
"uplinkPowerControlDedicated": {
"p0-UE-PUSCH": 0,
"deltaMCS-Enabled": "en0",
"accumulationEnabled": true,
"p0-UE-PUCCH": 0,
"pSRS-Offset": 3
},
"cqi-ReportConfig": {
"nomPDSCH-RS-EPRE-Offset": 0,
"cqi-ReportPeriodic": {
"setup": {
"cqi-PUCCH-ResourceIndex": 0,
"cqi-pmi-ConfigIndex": 38,
"cqi-FormatIndicatorPeriodic": {
},
"simultaneousAckNackAndCQI": true
}
}
},
"antennaInfo": {
"explicitValue": {
"transmissionMode": "tm1",
"ue-TransmitAntennaSelection": {
}
}
},
"schedulingRequestConfig": {
"setup": {
"sr-PUCCH-ResourceIndex": 0,
"sr-ConfigIndex": 15,
"dsr-TransMax": "n64"
}
}
}
}
}
}
}
}
}
}
}
}
]
2022-02-09T22:31:32.013860 [RRC ] [I] Proc "Connection Setup" - Starting...
2022-02-09T22:31:32.014060 [MAC ] [D] [ 2302] RA: ConRes: MAC PDU Contains Contention Resolution ID CE
2022-02-09T22:31:32.014061 [MAC ] [D] [ 2302] Msg3 buffer flushed
2022-02-09T22:31:32.014065 [MAC ] [I] [ 2302] RA: ConRes: Random Access Complete. c-rnti=0x46, ta=1
2022-02-09T22:31:32.014066 [RRC ] [D] Preparing RRC Connection Setup Complete
2022-02-09T22:31:32.014084 [RRC ] [D] SRB1 - Tx rrcConnectionSetupComplete (25 B)
2022-02-09T22:31:32.014085 [RRC ] [D] Content:
[
{
"UL-DCCH-Message": {
"message": {
"c1": {
"rrcConnectionSetupComplete": {
"rrc-TransactionIdentifier": 0,
"criticalExtensions": {
"c1": {
"rrcConnectionSetupComplete-r8": {
"selectedPLMN-Identity": 1,
"dedicatedInfoNAS": "07417108091010103254769802f07000050201d011d1"
}
}
}
}
}
}
}
}
]
2022-02-09T22:31:32.014091 [RRC ] [I] Finished Connection Setup successfully
2022-02-09T22:31:46.797740 [NAS ] [W] Timer T3410 expired after attach attempt 1/5: starting T3411
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
## Steps to reproduce the problem ##
- start srsepc on (PC1/ USRP1)
- start srsenb on (PC1/ USRP1)
- start srsue on (PC2/ USRP2)
## Conf files Attached ## conf_files.zip
This appears to be the same issue as in https://github.com/srsran/srsRAN/issues/770 and https://github.com/srsran/srsRAN/issues/803 I'd consider this to now be a verified issue. Issue 770 has a code snippet that claims to resolve this issue on 19.x, but the affected code has changed quite a bit since then and it's not obvious (to me) how to apply that particular fix to the current master branch.
I took another look at the logs. RRCConnectionSetupComplete did not receive grant to transmit.
UE --> RRCConnectionRequest --> eNB (success) UE <-- RRCConnectionSetup <-- eNB (success) UE --> RRCConnectionSetupComplete --> eNB (Failed)
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= --> UE log
2022-02-09T22:31:31.961634 [RRC ] [D] Setting UE contention resolution ID: 96997291055128
2022-02-09T22:31:31.961642 [RRC ] [D] SRB0 - Tx rrcConnectionRequest (6 B)
2022-02-09T22:31:31.961645 [RRC ] [I] Proc "Connection Request" - Waiting for RRCConnectionSetup/Reject or expiry
2022-02-09T22:31:31.962666 [MAC ] [D] [ 2251] BSR: New data available for lcid=0
2022-02-09T22:31:31.962666 [MAC ] [D] [ 2251] BSR: Triggering Regular BSR tti=2251
2022-02-09T22:31:31.962666 [MAC ] [D] [ 2251] BSR: Triggering SR procedure
2022-02-09T22:31:31.962667 [MAC ] [I] [ 2251] SR: PUCCH not configured. Starting RA procedure
2022-02-09T22:31:31.962667 [MAC ] [I] [ 2251] RA: INIT: Starting PRACH by MAC order
2022-02-09T22:31:31.962669 [MAC ] [D] [ 2251] RA: INIT: Selected preambleIndex=17 maskIndex=0 GroupA=52, GroupB=0
2022-02-09T22:31:31.968648 [PHY ] [I] [ 2257] PRACH: Transmitted preamble=17, tti_tx=2261, CFO=0.28 KHz, nof_sf=1, target_power=-104.0 dBm
2022-02-09T22:31:31.968692 [MAC ] [I] [ 2257] RA: PDCCH: seq=17, ra-rnti=0x2, ra-tti=2261, f_id=0
2022-02-09T22:31:31.975633 [MAC ] [D] [ 2263] SCHED: Searching RAR-RNTI=0x2, tti=2264
2022-02-09T22:31:31.976692 [MAC ] [D] [ 2265] SCHED: Searching RAR-RNTI=0x2, tti=2265
2022-02-09T22:31:31.977539 [MAC ] [D] [ 2265] SCHED: Searching RAR-RNTI=0x2, tti=2266
2022-02-09T22:31:31.977540 [PHY1 ] [D] [ 2266] PDCCH looking for rnti=0x2
2022-02-09T22:31:31.977557 [PHY1 ] [I] [ 2266] PDCCH: cc=0, f=1A, cce= 0, L=2, riv=100, pid=0, mcs={1}, ndi={0}, tpc_pucch=0, snr=35.3 dB
2022-02-09T22:31:31.977558 [MAC ] [D] [ 2265] RA: Rx: DL dci found RA-RNTI=2
2022-02-09T22:31:31.977580 [MAC ] [D] [ 2266] RA: Rx: RAR decoded successfully TBS=11
2022-02-09T22:31:31.977582 [PHY ] [D] [ 2266] RAR grant rar_grant=2266, msg3_tti=2272, stored in index=12
2022-02-09T22:31:31.977583 [MAC ] [I] [ 2266] RA: Rx: RAPID=17, TA=1, T-CRNTI=0x46
2022-02-09T22:31:31.977681 [MAC ] [D] [ 2266] RA: Rx: Waiting for Contention Resolution
2022-02-09T22:31:31.978580 [MAC ] [D] [ 2266] SCHED: Searching Temp-RNTI=0x46
2022-02-09T22:31:31.978581 [PHY0 ] [D] [ 2267] PDCCH looking for rnti=0x46
2022-02-09T22:31:32.013842 [RRC ] [D] SRB0 - Rx rrcConnectionSetup (20 B)
2022-02-09T22:31:32.014060 [MAC ] [D] [ 2302] RA: ConRes: MAC PDU Contains Contention Resolution ID CE
2022-02-09T22:31:32.014065 [MAC ] [I] [ 2302] RA: ConRes: Random Access Complete. c-rnti=0x46, ta=1
2022-02-09T22:31:32.014084 [RRC ] [D] SRB1 - Tx rrcConnectionSetupComplete (25 B)
2022-02-09T22:31:32.014604 [RLC ] [D] SRB1 Total buffer state - 1 SDUs (32 B)
2022-02-09T22:31:32.014604 [MAC ] [D] [ 2303] BSR: New data available for lcid=1
2022-02-09T22:31:32.014604 [MAC ] [D] [ 2303] BSR: Triggering Regular BSR tti=2303
2022-02-09T22:31:32.014605 [MAC ] [D] [ 2303] BSR: Triggering SR procedure
2022-02-09T22:31:32.014605 [MAC ] [I] [ 2303] SR: Signalling PHY sr_counter=1
2022-02-09T22:31:32.014619 [MAC ] [D] [ 2303] SCHED: Searching C-RNTI=0x46
2022-02-09T22:31:32.014619 [PHY0 ] [D] [ 2303] PDCCH looking for rnti=0x46
2022-02-09T22:31:32.015657 [PHY1 ] [D] [ 2304] PDCCH looking for rnti=0x46
2022-02-09T22:31:32.035583 [PHY1 ] [D] [ 2324] PDCCH looking for rnti=0x46
2022-02-09T22:31:32.037681 [PHY1 ] [I] [ 2326] PDCCH: cc=0, f=1A, cce= 6, L=0, riv=100, pid=1, mcs={6}, ndi={1}, tpc_pucch=0, snr=36.8 dB
2022-02-09T22:31:32.164667 [PHY0 ] [D] [ 2453] PDCCH looking for rnti=0x46
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= --> eNB log
2022-02-09T22:31:32.006492 [RRC ] [I] Tx SRB0 PDU, rnti=0x46 - rrcConnectionSetup (20 B)
2022-02-09T22:31:32.007314 [PHY0 ] [I] [ 2298] PDCCH: cc=0, rnti=0x46, f=1A, cce= 0, L=3, riv=100, pid=1, mcs={6}, ndi={1}, tpc_pucch=1, tti_tx_dl=2302
2022-02-09T22:31:32.013403 [PHY0 ] [I] [ 2304] PDCCH: cc=0, rnti=0x46, f=1A, cce= 0, L=3, riv=100, pid=0, mcs={0}, ndi={1}, tpc_pucch=1, tti_tx_dl=2308
2022-02-09T22:31:32.015314 [PHY0 ] [I] [ 2306] PDCCH: cc=0, rnti=0x46, f=1A, cce= 0, L=3, riv=100, pid=1, mcs={6}, ndi={1}, tpc_pucch=1, tti_tx_dl=2310
2022-02-09T22:31:32.021375 [PHY0 ] [I] [ 2312] PDCCH: cc=0, rnti=0x46, f=1A, cce= 0, L=3, riv=100, pid=0, mcs={0}, ndi={1}, tpc_pucch=1, tti_tx_dl=2316
2022-02-09T22:31:32.029346 [PHY0 ] [I] [ 2320] PDCCH: cc=0, rnti=0x46, f=1A, cce= 0, L=3, riv=100, pid=0, mcs={0}, ndi={1}, tpc_pucch=1, tti_tx_dl=2324
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
@FabianEckermann Hi Fabian, would you be able to guide here? I see that you raised similar concern earlier https://lists.srsran.com/pipermail/srsran-users/2017-July/001039.html
@jtang613 Thanks for your response and suggestions. I checked your ticket at https://github.com/srsran/srsRAN/issues/803. I see that your srsUE fails to complete RA procedure.
I double checked my log. My srsUE is able to transmit RRC Connection Request and receive RRC Connection Setup. However it failed further down to transmit RRC Connection Setup Complete. So code change at https://github.com/srsran/srsRAN/issues/770 may not be applicable to me.
Hi all, the issue here is time advance misconfiguration. Due to offsets in the TX and RX paths of the USRPs, the PRACH preamble can arrive before the start of the reception window. When this happens, the detected preamble is either incorrect or with a very high TA. Both result in either undetected RAR or incorrect Msg3.
We calibrated the time advance for some UHD versions. If using a very old (or very new one) this might not be accurate.
The solution to the issue is to use the parameter time_adv_nsamples in the rf section to set it to a value such that the detected preamble is correct and the TA is in the range eg 2-10 us.
Thanks for clarifying, @ismagom. Is there a way to identify from the logs whether the timing advance is configured too low/high? Or does it need to be found by trial and error? Plus, should the TA be configured on the base station or the UE side?
Note the time_adv_nsamples is not the same as the TA cmd sent by the RAR. The first one is the offset between TX and RX paths at the UE, the later is the offset between the reception of the PRACH and the start of the PRACH window at the eNB.
It's more trial and error, since the value you see in the TA at the eNB is incorrect if the PRACH arrives before the start of the window.
Yes, okay. I was also considering the the time_alignment_calibration parameter on the eNB, but I see that's not what you were referring to. So I'll try to alter the time_adv_samples at the UE side only. If I understand correctly, higher values create more delay and therefore will cause the signal to arrive later at the eNB.
I can confirm that adaptation of the time_adv_samples on the UE side solves the problem. I started with 10us * 11.52e6 samples/sec = 115 samples, then increased in steps of 5 while observing the reported SNR during PRACH. A good final configuration for me was 150 samples, which corresponds to about 13us.