srsRAN CU/DU and srsUE Control Plane Log Analysis Part 1

Introduction

I felt that after writing the previous post on the 5G Control Plane, that a supplemental post on the Control Plane procedures would aid in some absorption of the content. After agonizing over how to present the data (there is a lot to cover) I concluded that dissecting the SRS logs would provide granular insight. After all, if you aren’t using srsRAN and srsUE as tools to learn what you might not know then you are not taking full advantage of what SRS has to offer! If you find that you don’t have a USRP, then use my logs that I have uploaded to my github.

For this article I used the srsRAN gNB DU/CU “split” configuration that they have outlined in the srsRAN documentation.

For my configuration, I am running everything on the same machine

	Config File	Application Directory	Execute Command
Open5GS	/etc/open5gs/amf.yaml
srsRAN gNB-CU	~/srsRAN_Project/configs/cu.yml	~/srsRAN_Project/build/apps/cu	sudo ./srsdu -c <path/to/cu.yml>
srsRAN gNB-DU	~/srsRAN_Project/configs/du.yml	~/srsRAN_Project/build/apps/du	sudo ./srscu -c <path_to_du.yml>
srsUE	/etc/srsran/ue.conf		sudo srsue

Make sure Open5GS is running, then execute the gNB CU followed by the gNB DU and lastly, srsUE.

gNB CU Config

cu_cp:
  amf:
    addr: 127.0.0.5
    port: 38412
    bind_addr: 127.0.0.87
    supported_tracking_areas:
      - tac: 77
        plmn_list:
          - plmn: "00101"
            tai_slice_support_list:
              - sst: 1
  f1ap:
    bind_addr: 127.0.0.88

cu_up:
  nru:
    bind_addr: 127.0.0.88

log:
  filename: /tmp/cu.log
  all_level: debug

pcap:
  ngap_enable: true
  ngap_filename: /tmp/cu_ngap.pcap
  f1ap_enable: true  
  f1ap_filename: /tmp/gnb_f1ap.pcap

gNB DU Config

f1ap:
  cu_cp_addr: 127.0.0.88
  bind_addr: 127.0.0.87

ru_sdr:
  device_driver: uhd
  device_args: type=b200
  srate: 23.04
  otw_format: sc12
  clock: gpsdo  
  tx_gain: 75
  rx_gain: 40

cell_cfg:
  dl_arfcn: 368500
  band: 3
  channel_bandwidth_MHz: 20
  common_scs: 15
  plmn: "00101"
  tac: 77
  pci: 99
  pdcch:
    dedicated:
      ss2_type: common                                          
      dci_format_0_1_and_1_1: false                             
    common:
      ss0_index: 0
      coreset0_index: 12
  prach:
    prach_config_index: 1   

log:
  filename: /tmp/du.log
  all_level: debug

pcap:
  mac_enable: true
  mac_filename: /tmp/du_mac.pcap
  f1ap_enable: true
  f1ap_filename: /tmp/du_f1ap.pcap
  f1u_enable: true
  f1u_filename: /tmp/du_f1u.pcap
  rlc_enable: true
  rlc_rb_type: all
  rlc_filename: /tmp/du_rlc.pcap

srsUE Config

[rf]
freq_offset = 0
tx_gain = 100
#rx_gain = 10
srate = 23.04e6
nof_antennas = 1
device_args = sync=gpsdo,clock=gpsdo
time_adv_nsamples = 300
continuous_tx     = auto

[rat.eutra]
dl_earfcn = 3350
nof_carriers = 0
[rat.nr]
bands = 3
nof_carriers = 1
max_nof_prb = 106
nof_prb = 106

[pcap]
enable = mac_nr,nas
mac_filename = /tmp/ue_mac.pcap
mac_nr_filename = /tmp/ue_mac_nr.pcap
nas_filename = /tmp/ue_nas.pcap

[log]
all_level = debug
phy_lib_level = debug
all_hex_limit = 32
filename = /tmp/ue.log
file_max_size = -1

[usim]
mode = soft
algo = milenage
opc  = 63BFA50EE6523365FF14C1F45F88737D
k    = 00112233445566778899aabbccddeeff
imsi = 001010123456780
imei = 353490069873319

[rrc]
ue_category       = 4
release           = 15

[nas]
apn = apn
apn_protocol = ipv4

SRS Logs

Some points for looking at the log files you get when using debug level logging with srsRAN and srsUE.

The logs are a bit like a puzzle, when looking at transactions between the gNB and the UE, not everything will line up by timestamp, or by the TTI stamp
- srsRAN and srsUE have different TTI stamp formats… I suggest editing your log file to align the two formats
- Certain protocols do not have TTI stamps (RLC, PDCP, RRC)
- Certain protocols/messages provide transmit TTI and receive TTI… Pay attention to these along with the timestamp. (PUSCH Transmission, FAPI Indication Slot,SCHED slot_rx)
CU/DU split logs add a bit of complexity due to the F1-C interface between the two components, but largely we will just focus on the 5G NR Control Plane protocol stack.
- The CU Log is sparse compared to the DU log, though it contains PDCP and RRC messages which are key for identifying a majority of the major procedures
When I started collecting logs for this article, I was using one machine for srsUE and one machine for srsRAN. The time difference between the UE and gNB logs was significant (+/- ~2 seconds) to essentially throw the logs away for the sake of time stamp analysis.
There are some lines/protocols that are redundant. Find a common string in those lines and remove those lines from the log. Make sure you aren’t removing information that might be helpful from other lines.
- I generally use Sublime text and will use “find all” and will copy and paste the lines to a blank document to make sure it is only removing the lines I want removed. Otherwise, I will adjust the string that I am using.
If you have patience (or skills) using programs like Excel can be helpful. Python can also be helpful for automating your log clean up
When I have cleaned up the logs to my liking, I will pre-pend srsUE protocols with “UE-” so that I can merge the UE and gNB logs and then sort by time.
- Some lines do have timestamps and will fall victim to sorting by timestamp…
Compare logs to PCAPs
- For most major procedures, the PCAPs will give time stamps that will CLOSELY align with the log timestamps. Though no TTI data is given in the PCAPs.
- PCAPs will provide details of what you are seeing in the logs when comparing TBS, MAC subPDUs, LCID, etc.
Back to point #1 where I mention that the logs are like a puzzle….
- I try to match every PHY layer Physical Channel transmission with it’s subsequent reception and vice versa.
- Sometimes the gNB will schedule an UL Physical Channel and the gNB will attempt to receive that Physical Channel at the PHY layer by indicating [PHY ][ TTI] PUCCH: or [PHY ][TTI] PUSCH: though on the UE side you may notice that the UE never transmitted a PUCCH or PUSCH.
- Each entity (gNB/UE) runs processes concurrently.
  - gNB receives a PUSCH transmission
  - gNB schedules subsequent PDCCH/PDSCH
  - gNB is decoding and processing PUSCH data
    - I like to group these processes together and then order them logically so that it might look something like this
      - gNB PUSCH reception
      - gNB PUSCH decoding
      - gNB PUSCH processing
      - gNB PUSCH data generation
      - gNB PDCCH/PDSCH scheduling
      - gNB PDCCH/PDSCH transmission
- Some procedures may require retransmission
  - Sometimes this will be obvious in the PCAPs, and sometimes it will not
    - You will see in the analysis of the logs here that (and I observe this in almost all of my log collections) that the initial UE HARQ ACK after receiving Contention Resolution is received in the wrong TTI and requires a retransmission of Contention Resolution and RRC Setup. The PCAP will only show that these messages were sent and received one time. The logs will show retransmissions.

SRS Log Control Plane Protocols

srsUE	srsRAN gNB DU	srsRAN gNB CU
PHY	PHY
PHY-LIB	FAPI
MAC	MAC
MAC-NR	SCHED	PDCP
RLC	RLC	RRC
RLC-NR	SCTP-GW	SCTP-GW
PDCP-NR	GNB	NGAP
RRC-NR	DU	CU
NAS5G	DU-F1	CU-CP
	DU-MNG	CU-CP-F1
		CU-UEMNG

USIM	RF	SEC
STCK	UDP-GW	UDP-GW

MIB

2025-01-09T19:06:09.126045 [FAPI    ][   592.0] DL_TTI.request slot=592.0, is_last_message_in_slot=true
	- SSB pointA=40 L_max=4 pci=99 k_SSB=6

The MIB is broadcast periodically by the gNB. The SSB contains the PBCH, which is decoded by the UE to extract the MIB.

SSB Periodicity by SIB1 parameter "ssb-PeriodicityServingCell": "ms10",
An SSB is transmitted every 10 millisecond

FAPI requests a TTI of SFN 592 Slot 0 to transmit the SSB

2025-01-09T19:06:09.131249 [UE-PHY2-NR][ 592.0] SSB-CSI: rsrp=-20.6 epre=-20.5 n0=-37.9 snr=+17.3
2025-01-09T19:06:09.131327 [UE-PHY_LIB][    0]  PBCH-NR Rx: crc=OK
2025-01-09T19:06:09.131332 [UE-PHY2-NR][ 592.0] PBCH-MIB: sfn=592 ssb_idx=0 hrf=n scs=15 ssb_offset=6 dmrs_typeA_pos=pos2 coreset0=12 ss0=0

At SFN 590 Slot 0, the UE measures the the SSB Channel State and proceeds to decode the PBCH.

UE receives PBCH and passes CRC Check
UE decodes the MIB
- hrf = half radio frame
- coreset0 & ss0 (searchSpaceZero) are used to locate the PDCCH 1_0 that provides resource allocation for the PDSCH carrying SIB1

SIB1

2025-01-09T19:06:09.127122 [FAPI    ][   592.1] DL_TTI.request slot=592.1, is_last_message_in_slot=false
	- PDCCH bwp=2:96 symb=0:1 nof_dcis=1
	- PDSCH rnti=0xffff bwp=2:96 symb=2:12 CW: tbs=80 mod=2 rv_idx=0
2025-01-09T19:06:09.127145 [FAPI    ][   592.1] Tx_Data.request slot=592.1 nof_pdus=1

The gNB FAPI requests slots for the PDCCH and PDSCH with SIB1

Something I am curious about here, is what triggers the gNB to transmit these Physical Channels? And why the PHY logs for the gNB do not explicitly state that the PDCCH and PDSCH are transmitted?

PDCCH DCI 1_0
PDSCH with SI-RNTI (0xffff) and transport block size of 80 bytes
FAPI Data Transmission Slot request (1 PDU)

2025-01-09T19:06:09.132320 [UE-PHY_LIB][    0]  PDCCH Rx: K=65; E=432; M=216; n=9;
2025-01-09T19:06:09.132336 [UE-PHY_LIB][    0]  Found DCI in L=2,ncce=0
2025-01-09T19:06:09.132360 [UE-PHY0-NR][ 592.1] PDCCH: cc=0, si-rnti=0xffff dci=1_0
2025-01-09T19:06:09.132375 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 640, C=1, K=720, F=720, Bp=656
2025-01-09T19:06:09.132382 [UE-MAC-NR ][ 592.1] new_grant_dl(): cc_idx=0, tti=5921, rnti=65535, pid=0, tbs=80, ndi=0
2025-01-09T19:06:09.132470 [UE-PHY_LIB][    0]  PDSCH: RNTI=65535 (0xffff); nid=99; cinit=2147450979 (0x7fff8063);
2025-01-09T19:06:09.132474 [UE-PHY_LIB][    0]  SCH Rx: RM CB 0: E=1728; F=64; BG=2; Z=72; RV=0; Qm=2; Nref=25344;
2025-01-09T19:06:09.132524 [UE-PHY_LIB][    0]  SCH Rx: CB 0/1 iter=1 CRC=OK
2025-01-09T19:06:09.132526 [UE-PHY_LIB][    0]  SCH Rx: TB: TBS=640; CRC=OK
2025-01-09T19:06:09.132540 [UE-PHY0-NR][ 592.1] PDSCH: cc=0 pid=0 si-rnti=0xffff tbs=80

UE detects and decodes PDCCH DCI 1_0 with SI-RNTI

K (Number of coded symbols for PDCCH)
E (Encoded bits for PDCCH)
M (Number of Resource Elements for PDCCH)
n (Number of Control Channel Elements for PDCCH)
L (Aggregation Level)
ncce (Position of the first CCE of DCI)

The LDPC Code Block Segmentation of the PDSCH

TBS=640 (in bits) equals 80 bytes
C=1 (Number of Code Blocks)
K=720 (Size of the Code Block) 90 Bytes
F=720 (Number of Filler Bits)
Bp=656 (Payload Bits per Code Block)

PDSCH cinit

Initial Value of the Psuedo-Random Sequence used for Scrambling the PDSCH modulation symbols (used for mitigating interference)

nRNTI = 65535

q = Input parameter (likely 0 for PDSCH)

n_ID = PCI 99

Since SIB1 uses the DL-SCH Transport Channel, the PHY Lib receives the SCH (SCH Rx). The PHY receives the Transport Block which is segmented into smaller blocks, called Code Blocks.

Code Block 0 of 1 in Transport Block with CRC check passing
Transport Block of 80 Bytes with CRC check passing

UE receives PDSCH with SI-RNTI and TBS of 80

2025-01-09T19:06:09.132541 [UE-MAC-NR ][ 592.1] tb_decoded(): tti=5921, rnti=0xFFFF, pid=0, tbs=80, ndi=0, result=OK
2025-01-09T19:06:09.132552 [UE-MAC-NR ][ 592.1] DL 0:  newTX tbs=80, rv=0, ack=OK, ndi=0
2025-01-09T19:06:09.133122 [UE-MAC-NR ][ 592.2] Handling MAC BCCH PDU (80 B)
2025-01-09T19:06:09.133122 [UE-RLC-NR ]BCCH TXSCH message received.
2025-01-09T19:06:09.133271 [UE-RRC-NR ]BCCH-DLSCH - Rx systemInformationBlockType1 (80 B)
2025-01-09T19:06:09.133282 [UE-RRC-NR ]Processing SIB1 (1/1)
2025-01-09T19:06:09.133287 [UE-RRC-NR ]SIB1 received, CellID=4095
2025-01-09T19:06:09.133289 [UE-RRC-NR ]Set Constants and Timers: 
2025-01-09T19:06:09.133290 [UE-MAC-NR ][ 592.2] Set RACH common config (Config Index 1, preambleTransMax 7, Response Window 10)
2025-01-09T19:06:09.133303 [UE-RRC-NR ]Proc "Cell Selection" - Completed with success.
2025-01-09T19:06:09.133303 [UE-RRC-NR ]Proc "Cell Selection" - SIB1 acquired successfully
2025-01-09T19:06:09.133534 [UE-RRC-NR ]PHY configuration with SIB parameters completed.

The Transport Block is then passed to upper layers

MAC decodes TB received at 592.1
- ndi (New Data Indicator) 0 (not new data)
RLC handles BCCH / DL-SCH message to be sent to RRC layer
- SIB1 of 80 Bytes
RRC Processes SIB1, acquires Layer3 Cell Identity, Sets Constants and Timers, and determines that the cell has been selected .
MAC processes RACH Common Configuration parameters in preparation to send MSG1.

Prepare RRC Setup Request

2025-01-09T19:06:09.133307 [UE-RRC-NR ]Proc "Setup Request" - Configuring serving cell...
2025-01-09T19:06:09.133308 [UE-RRC-NR ]Preparing RRC Setup Request
2025-01-09T19:06:09.133314 [UE-RRC-NR ]Setting UE contention resolution ID: 23128943880518
2025-01-09T19:06:09.133322 [UE-RRC-NR ]SRB0 - Tx rrcSetupRequest (6 B)
2025-01-09T19:06:09.133325 [UE-RLC-NR ]SRB0: Tx SDU, queue size=1, bytes=6
2025-01-09T19:06:09.133326 [UE-RRC-NR ]Proc "Setup Request" - Updating dedicatedInfoNAS in RRC
2025-01-09T19:06:09.133326 [UE-RRC-NR ]Proc "Setup Request" - Waiting for RRCSetup/Reject or expiry

At this point, the UE creates the RRC Setup Request message.

Contention Resolution ID is used in the RRC Setup Request Message as the ue-Identity.
RRC uses SRB0 to transmit RRC Setup Request, the message will be 6 bytes
RLC receives the message and queues the message
- RRC Setup Request is not sent until Message 3

The UE uses the t300 timer from SIB1 to wait for the RRC Setup message (Waiting for RRCSetup/Reject or expiry)

t300: ms1000

Random Access Message 1 (Preamble)

2025-01-09T19:06:09.133319 [UE-PHY-SA ][ 592.3] Setting new PHY configuration ARFCN=368500, PCI=99
2025-01-09T19:06:09.133321 [UE-PHY-SA ][ 592.3] PRACH: cell.id=99, configIdx=1, rootSequence=1, zeroCorrelationConfig=0, freqOffset=5
2025-01-09T19:06:09.133433 [UE-PHY-SA ][ 592.3] Finished setting new PRACH configuration.
2025-01-09T19:06:09.133434 [UE-PHY-SA ][ 592.3] PHY:   Set TA offset: n_ta_offset: 400, ta_usec: 13.0
2025-01-09T19:06:09.134201 [UE-MAC-NR ][ 592.3] Starting PRACH by MAC order
2025-01-09T19:06:09.134202 [UE-PHY-SA ][ 592.4] PRACH: prepare to send preamble 0
2025-01-09T19:06:09.140087 [UE-PHY-SA ][ 593.0] PRACH Buffer: Ready to send at tti: 5934 (now is 5930)
2025-01-09T19:06:09.140090 [UE-PHY_LIB][    0]  N_zc: 839, N_cp: 2376, N_seq: 18432, N_ifft_prach=18432 begin: 2743
2025-01-09T19:06:09.140131 [UE-MAC-NR ][ 592.9] nof_lcids_with_data=1, nof_lcgs_with_data=1, last_non_zero_lcg=0 [UE-lcg0=6, ] [UE-lcid0=6, ]
2025-01-09T19:06:09.140402 [UE-PHY-SA ][ 593.0] PRACH: Transmitted preamble=0, tti_tx=5934, CFO=-0.00 KHz, nof_sf=1, target_power=-1.0 dBm
2025-01-09T19:06:09.140442 [UE-MAC-NR ][ 592.9] prach_occasion=0, preamble_index=0, ra-rnti=0x39, ra-tti=5934, s_id=0, t_id=4, f_id=0, ul_carrier_id=0
2025-01-09T19:06:09.140453 [UE-MAC-NR ][ 592.9] Calculated ra_window_start=5937, ra_window_length=10

The UE uses the parameters from SIB1 rach-ConfigCommon to prepare the MSG1 Preamble sent on the PRACH physical channel.

prach-ConfigurationIndex: 1
prach-RootSequenceIndex: l839
- l839: 1
zeroCorrelationZoneConfig: 0
msg1-FDM: one
msg1-FrequencyStart: 8

The PRACH is ready to be sent and is buffered at 593.0 to be sent at TTI 593.4

Message 1 PRACH Preamble is transmitted at TTI 593.4 with the calculated RA-RNTI 0x39 (52)

The UE sets the Message 2 Random Access Response Window based on the SIB1 parameter

ra-ResponseWindow: sl10

2025-01-09T19:06:09.140136 [FAPI    ][   593.4] UL_TTI.request slot=593.4
	- PRACH pci=99 format=0 fd_ra=0:1 symb=0 z_corr=0 res_config_idx=0
2025-01-09T19:06:09.145958 [PHY     ][   593.4] PRACH: rsi=1 rssi=+15.6dB detected_preambles=[{idx=0 ta=2.34us detection_metric=8.3}] t=679.1us
2025-01-09T19:06:09.145971 [FAPI    ][   593.9] RACH.indication slot=593.4
	- PRACH symb_idx=0 slot_idx=4 rssi=15.6 nof_preambles=1:
		- PREAMBLE index=0 ta_ns=2343 pwr=9.2 snr=9.0
2025-01-09T19:06:09.146130 [SCHED   ][   594.0] Processed slot events pci=99:
        - PRACH: slot=593.4 pci=99 preamble=0 ra-rnti=0x39 temp_crnti=0x4601 ta_cmd=4

The gNB FAPI requests UL Slot of 593.4 for the PRACH preamble (MSG1) which is receives by the PHY, which then traverses FAPI to the MAC scheduler where the event is processed.

RA-RNTI (will be used to “address” the UE for MSG2
temp_crnti: gNB assigns this to the UE in the MSG2 payload
ta_cmd: Timing Advance Command, part of the MSG2 payload

Random Access Message 2 (Random Access Response)

2025-01-09T19:06:09.146146 [SCHED   ][   594.0] Slot decisions pci=99 t=33us (1 PDSCH, 0 PUSCHs):
	- DL PDCCH: rnti=0x39 type=ra-rnti cs_id=0 ss_id=1 format=1_0 cce=0 al=4 
        - RAR PDSCH: ra-rnti=0x39 rb=[0..3) symb=[1..14) tbs=10 mcs=0 rv=0 grants (1): tc-rnti=0x4601: rapid=0 ta=4 
2025-01-09T19:06:09.146159 [FAPI    ][   594.0] DL_TTI.request slot=594.0, is_last_message_in_slot=false
	- PDCCH bwp=2:96 symb=0:1 nof_dcis=1
	- SSB pointA=40 L_max=4 pci=99 k_SSB=6
	- PDSCH rnti=0x39 bwp=2:96 symb=1:13 CW: tbs=10 mod=2 rv_idx=0
2025-01-09T19:06:09.146194 [FAPI    ][   594.0] Tx_Data.request slot=594.0 nof_pdus=1
2025-01-09T19:06:09.146257 [PHY     ][   594.0] PDCCH: rnti=0x0039 ss_id=1 format=1_0 cce=0 al=4 t=44.2us
2025-01-09T19:06:09.146266 [PHY     ][   594.0] PDSCH: rnti=0x0039 prb=[0, 3) symb=[1, 14) mod=QPSK rv=0 tbs=10

the gNB schedules PDCCH DCI 1_0 with CRC scrambled by RA-RNTI and PDSCH carrying RAR payload with a TBS of 10 bytes and then transmits the physical channels in their scheduled slots (594.0)

2025-01-09T19:06:09.151651 [UE-PHY_LIB][    0]  Found DCI in L=2,ncce=0
2025-01-09T19:06:09.151657 [UE-PHY1-NR][ 594.0] PDCCH: cc=0, ra-rnti=0x0039 dci=1_0
2025-01-09T19:06:09.151677 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 80, C=1, K=160, F=160, Bp=96
2025-01-09T19:06:09.151682 [UE-MAC-NR ][ 594.0] new_grant_dl(): cc_idx=0, tti=5940, rnti=57, pid=0, tbs=10, ndi=0
2025-01-09T19:06:09.152066 [UE-PHY_LIB][    0]  PDSCH: RNTI=57 (0x39); nid=99; cinit=1867875 (0x1c8063);
2025-01-09T19:06:09.152069 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 80, C=1, K=160, F=160, Bp=96
2025-01-09T19:06:09.152071 [UE-PHY_LIB][    0]  SCH Rx: RM CB 0: E=720; F=64; BG=2; Z=16; RV=0; Qm=2; Nref=25344;
2025-01-09T19:06:09.152114 [UE-PHY_LIB][    0]  SCH Rx: CB 0/1 iter=1 CRC=OK
2025-01-09T19:06:09.152115 [UE-PHY_LIB][    0]  SCH Rx: TB: TBS=80; CRC=OK
2025-01-09T19:06:09.152137 [UE-PHY1-NR][ 594.0] PDSCH: cc=0 pid=0 ra-rnti=0x39 prb=(2,4) symb=(1,13) CW0: mod=QPSK tbs=10 CRC=OK

As soon as the UE sends MSG1 it begins searching for PDCCH scrambled with the RA-RNTI that was sent in the preamble. Upon detecting the PDCCH DCI 1_0 it gains resource allocation via Downlink Grant for the PDSCH carrying the RAR payload.

2025-01-09T19:06:09.152139 [UE-MAC-NR ][ 594.1] tb_decoded(): cc_idx=0, tti=5940, rnti=0x39, pid=0, tbs=10, ndi=0, rv=0, result=OK
2025-01-09T19:06:09.152243 [UE-MAC-NR ][ 594.1] DL RAPID: 0, Temp C-RNTI: 0x4601, TA: 4, UL Grant: [UE-01 b8 01 c0 ]
2025-01-09T19:06:09.152245 [UE-MAC-NR ][ 594.1] PROC RA NR: Setting UL grant and prepare Msg3
2025-01-09T19:06:09.152252 [UE-PHY-SA ][ 594.0] Setting RAR Grant: ra-rnti=0x4601 dci=RAR ss=rar hop=0 f_alloc=0xdc t_alloc=0x0 mcs=0 tpc=7 csi=0 
2025-01-09T19:06:09.152265 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 88, C=1, K=180, F=180, Bp=104
2025-01-09T19:06:09.152267 [UE-PHY-SA ][ 594.0] PHY:   Set TA RAR: ta_cmd: 4, n_ta: 464, ta_usec: 15.1
2025-01-09T19:06:09.152268 [UE-MAC-NR ][ 594.1] Waiting for Contention Resolution
2025-01-09T19:06:09.153509 [UE-MAC-NR ][ 594.2] new_grant_ul(): cc_idx=0, tti=5946, rnti=0x4601, pid=0, tbs=11, ndi=0, rv=0, is_rar=1
2025-01-09T19:06:09.153510 [UE-MAC-NR ][ 594.2] BSR:   Cancelling SR procedure due to UL grant

The PHY layer passes the transport block to the MAC layer where the RAR payload is decoded.

DL RAPID
TC-RNTI
Timing Advance
Uplink Grant
- Transmission Power Control for MSG3 PUSCH
- Frequency Hopping Flag
- MSG3 PUSCH Frequency Resource Allocation
- MSG3 PUSCH Time Resource Allocation
- Modulation and Coding Scheme
- CSI Request

The Uplink Grant part of the RAR payload provides resources for the UE to transmit MSG3 on the PUSCH (it’s first PUSCH transmission.) The UE sets the Timing Advance and begins waiting for Message 4 (Contention Resolution).

Random Access Message 3 (Scheduled Transmission/RRC Setup Request)

2025-01-09T19:06:09.152148 [SCHED   ][   594.6] Slot decisions pci=99 t=16us (0 PDSCHs, 1 PUSCH):
	- UE PUSCH: ue=1024 tc-rnti=0x4601 h_id=0 rb=[8..11) symb=[0..14) tbs=11 rv=0 nrtx=0 msg3_delay=6
2025-01-09T19:06:09.152181 [FAPI    ][   594.6] UL_TTI.request slot=594.6
 	- PUSCH rnti=0x4601 bwp=0:106 symb=0:14 mod=2 CW: tbs=11 rv_idx=0 harq_id=0

The gNB schedules the MSG3 PUSCH transmission for arrival at TTI 594.6 with an expected TBS of 11 bytes.

2025-01-09T19:06:09.153512 [UE-MAC-NR ][ 594.2] Building new MAC PDU (11 B)
2025-01-09T19:06:09.153513 [UE-MAC-NR ][ 594.2] Adding SDUs for LCID=0 (max 11 B)
2025-01-09T19:06:09.153515 [UE-RLC-NR ]SRB0: Complete SDU scheduled for tx. Stack latency: 20201 us
2025-01-09T19:06:09.153516 [UE-RLC-NR ]SRB0: Tx Transparent Mode PDU, queue size=0, bytes=0
2025-01-09T19:06:09.153517 [UE-MAC-NR ][ 594.2] Read 6 B from RLC
2025-01-09T19:06:09.153520 [UE-MAC-NR ][ 594.2] 3 B remaining PDU
2025-01-09T19:06:09.153524 [UE-MAC-NR ][ 594.2] UL CCCH48: len=6 SBSR: lcg=0 bs=1 PAD: len=1
2025-01-09T19:06:09.153524 [UE-MAC-NR ][ 594.2] Generated MAC PDU (11 B)
2025-01-09T19:06:09.153525 [UE-MAC    ][ 594.2] UL 0:  New TX for Msg3, rv=0, tbs=11
2025-01-09T19:06:09.153654 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 88, C=1, K=180, F=180, Bp=104
2025-01-09T19:06:09.153678 [UE-PHY_LIB][    0]  SCH Tx: CB 0: appending TB CRC=00a6df
2025-01-09T19:06:09.153687 [UE-PHY_LIB][    0]  SCH Tx: RM CB 0: E=792; F=76; BG=2; Z=18; RV=0; Qm=2; Nref=25344;
2025-01-09T19:06:09.153692 [UE-PHY_LIB][    0]  PUSCH: RNTI=17921 (0x4601); nid=99; cinit=587235427 (0x23008063);
2025-01-09T19:06:09.153874 [UE-PHY0-NR][ 594.2] PUSCH: cc=0 pid=0 ra-rnti=0x4601 prb=(8,10) symb=(0,13) CW0: mod=QPSK tbs=11 R=0.131 rv=0  t=32 us cfo=2 tti_tx=5946

Once receiving the UL Grant for MSG3, the UE begins building the payload for the message.

MAC PDU of 11 Bytes
RLC passes the 6 byte RRC Setup Request message (previous queued) to the MAC layer
- RLC Tranparent Mode (SRB0)
MAC adds subheaders for
- UL CCCH (LCID 52)
- Short BSR (LCID 61)
- Padding (LCID 63)

The MAC PDU is now generated and is passed to the PHY layer for transmission on PUSCH. The Transmit TTI is set to 594.6

2025-01-09T19:06:09.157430 [PHY     ][   594.6] PUSCH: rnti=0x4601 h_id=0 prb=[8, 11) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=OK
2025-01-09T19:06:09.157441 [FAPI    ][   595.1] CRC.indication slot=594.6
	- CRC rnti=0x4601 harq_id=0 tb_status=OK ta_ns=-7 sinr=34.2 rsrp=0.0
2025-01-09T19:06:09.157464 [FAPI    ][   595.1] Rx_Data.indication slot=594.6
	- DATA rnti=0x4601 harq_id=0 tbs=11

The gNB receives the PUSCH in the allocated TTI, at the FAPI layer the CRC check is conducted and is determined that the gNB has received data from the UE.

2025-01-09T19:06:09.157582 [MAC     ][   595.1] UL rnti=0x4601 subPDUs: [CCCH48: len=6, SBSR: lcg=0 bs=1, PAD: len=1]
2025-01-09T19:06:09.157862 [RLC     ]du=0 ue=0 SRB0 DL: RLC TM created. queue_size=8
2025-01-09T19:06:09.157870 [RLC     ]du=0 ue=0 SRB0 UL: RLC TM created. 
2025-01-09T19:06:09.157930 [RLC     ]du=0 ue=0 SRB1 DL: RLC AM configured. tx_sn_size=12 pdcp_sn_len=12 t_poll_retx=45 max_retx=8 poll_pdu=-1 poll_byte=-1 queue_size=32 queue_size_bytes=64000 max_window=0
2025-01-09T19:06:09.158025 [RLC     ]du=0 ue=0 SRB1 UL: RLC AM configured. rx_sn_size=12 t_reassembly=35 t_status_prohibit=0 max_sn_per_status={na}
2025-01-09T19:06:09.158144 [MAC     ][   595.2] UL rnti=0x4601 lcid=52 CE: Discarding remaining subPDUs
2025-01-09T19:06:09.158189 [MAC     ][   595.2] ue=0 crnti=0x4601 proc="MAC UE Creation": UE UL context created successfully
2025-01-09T19:06:09.159408 [MAC     ][   595.3] ue=0 crnti=0x4601 proc="MAC UE Creation": finished successfully
2025-01-09T19:06:09.159414 [SCHED   ][   595.3] Processed slot events pci=99:
	- UE creation: ue=0 rnti=0x4601 pci=99
2025-01-09T19:06:09.159419 [MAC     ][   595.3] UL subPDU rnti=0x4601 ue=0 lcid=0 CE: Forwarding UL SDU of 6 bytes
2025-01-09T19:06:09.159430 [RLC     ]du=0 ue=0 SRB0 UL: RX SDU. sdu_len=6
2025-01-09T19:06:09.160997 [RRC     ] [D] ue=0 c-rnti=0x4601: Rx CCCH UL rrcSetupRequest (6 B)

The message received is using SRB0, where RLC is still in transparent mode and PDCP has not been configured yet. The message will start being decoded at the MAC layer, then onto the RLC layer where SRB0 Transparent Mode is created for the received message and the subsequent RRC Setup message. The RLC layer will also configure SRB1, which will be sent to the UE in the RRC Setup message.

The MAC layer begins creating the UE Context (triggered by the RRC Setup Request) where the scheduler at the MAC layer processes the message and successfully creates the UE Context (UE Creation).

MAC forwards subPDU to the RLC layer. The RLC layer receives the 6 byte SDU and sends to the RRC layer using the UL CCCH Logical Channel and SRB0.

Random Access Message 4 (Contention Resolution)

When using the srsRAN DU/CU configs compared to the standard single config file srsRAN, the DU/CU configuration sends separate messages for Contention Resolution and RRC Setup to the UE.

Where the standard configuration sends Contention Resolution and RRC Setup together. This may have to do with the DU/CU configuration where the entities are split and the RRC Setup message being generated at the CU’s RRC layer, and Contention Resolution being generated at the DU’s MAC layer.

srsRAN standard config with CR and RRC Setup combined into single message

2025-01-09T19:06:09.160083 [SCHED   ][   595.4] Slot decisions pci=99 t=29us (1 PDSCH, 0 PUSCHs):
	- DL PDCCH: rnti=0x4601 type=tc-rnti cs_id=0 ss_id=1 format=1_0 cce=0 al=4  dci: h_id=0 ndi=1 rv=0 mcs=0 res_ind=0
	- UE PDSCH: ue=0 c-rnti=0x4601 h_id=0 rb=[0..2) symb=[1..14) tbs=7 mcs=0 rv=0 nrtx=0 k1=4 dl_bo=0 olla=0.00 grants: lcid=62: size=6
2025-01-09T19:06:09.160095 [FAPI    ][   595.4] DL_TTI.request slot=595.4, is_last_message_in_slot=false
	- PDCCH bwp=2:96 symb=0:1 nof_dcis=1
	- PDSCH rnti=0x4601 bwp=2:96 symb=1:13 CW: tbs=7 mod=2 rv_idx=0
2025-01-09T19:06:09.160138 [MAC     ][   595.4] DL PDU: ue=0 rnti=0x4601 size=7: CON_RES: id=159207be946
2025-01-09T19:06:09.160140 [FAPI    ][   595.4] Tx_Data.request slot=595.4 nof_pdus=1
2025-01-09T19:06:09.160201 [PHY     ][   595.4] PDCCH: rnti=0x4601 ss_id=1 format=1_0 cce=0 al=4 t=50.6us
2025-01-09T19:06:09.160207 [PHY     ][   595.4] PDSCH: rnti=0x4601 h_id=0 k1=4 prb=[0, 2) symb=[1, 14) mod=QPSK rv=0 tbs=7

The gNB schedules the PDCCH DCI 1_0 with TC-RNTI that will provide resource allocation for the PDSCH carrying Contention Resolution with a TBS of 7.

FAPI requests DL TTI of 595.4
MAC layer generated the DL PDU containing the Contention Resolution payload
- LCID 62
- Contention Resolution Identity ( CON_RES: id=)
FAPI indicates a data transmission request for TTI 595.4
PDCCH DCI 1_0 and PDSCH with Contention Resolution are transmitted at TTI 595.4

2025-01-09T19:06:09.165614 [UE-PHY_LIB][    0]  Found DCI in L=2,ncce=0
2025-01-09T19:06:09.165677 [UE-PHY_LIB][    0]  PDCCH Rx: K=65; E=432; M=216; n=9;
2025-01-09T19:06:09.165722 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 56, C=1, K=120, F=120, Bp=72
2025-01-09T19:06:09.165700 [UE-PHY0-NR][ 595.4] PDCCH: cc=0, c-rnti=0x4601 dci=1_0 ss=common0 L=2 cce=0 f_alloc=0x60 t_alloc=0x0 vrb_to_prb_map=0 mcs=0 ndi=1 rv=0 harq_id=0 dai=0 pucch_tpc=1 pucch_res=0 harq_feedback=3 
2025-01-09T19:06:09.165732 [UE-PHY0-NR][ 595.4] PDCCH: c-rnti=0x4601 dci=0_0 ss=common3 L=2 cce=0 EPRE=+9.63, RSRP=+9.38, corr=0.943 nof_bits=41 crc=OK
2025-01-09T19:06:09.165735 [UE-MAC-NR ][ 595.4] new_grant_dl(): cc_idx=0, tti=5954, rnti=17921, pid=0, tbs=7, ndi=1, rv=0
2025-01-09T19:06:09.165737 [UE-MAC-NR ][ 595.4] Considering NDI in pid=0 to be toggled for first Temporal C-RNTI
2025-01-09T19:06:09.165801 [UE-PHY_LIB][    0]  PDSCH: RNTI=17921 (0x4601); nid=99; cinit=587235427 (0x23008063);
2025-01-09T19:06:09.165807 [UE-PHY_LIB][    0]  SCH Rx: RM CB 0: E=480; F=48; BG=2; Z=12; RV=0; Qm=2; Nref=25344;
2025-01-09T19:06:09.165841 [UE-PHY_LIB][    0]  SCH Rx: CB 0/1 iter=1 CRC=OK
2025-01-09T19:06:09.165843 [UE-PHY_LIB][    0]  SCH Rx: TB: TBS=56; CRC=OK
2025-01-09T19:06:09.165861 [UE-PHY0-NR][ 595.4] PDSCH: cc=0 pid=0 c-rnti=0x4601 prb=(2,3) symb=(1,13) CW0: mod=QPSK tbs=7 R=0.150 rv=0 CRC=OK

The UE detected PDCCH DCI 1_0 with its allocated TC-RNTI and receives resource allocation (new_grant_dl) for PDSCH with CR payload. Observe that harq_id=0 is associated with Contention Resolution.

The UE also attempts to detect PDCCH with DCI 0_0 for PUSCH transmission resource allocation.

DCI 0_0 was not sent by the gNB yet.

“Considering NDI in pid=0 to be toggled for first temporary C-RNTI”
- The UE determines whether the New Data Indicator (NDI) will be toggled in the subsequent UE transmission
  - Critical for the follow on HARQ Procedures to acknowledge the receipt of the data
PDSCH is received with TBS of 7 bytes

2025-01-09T19:06:09.165862 [UE-MAC-NR ][ 595.4] tb_decoded(): cc_idx=0, tti=5954, rnti=0x4601, pid=0, tbs=7, ndi=1, rv=0, result=OK
2025-01-09T19:06:09.165866 [UE-MAC-NR ][ 595.4] Delivering PDU=7 bytes to Dissassemble and Demux unit (Temporal C-RNTI) not implemented
2025-01-09T19:06:09.165867 [UE-MAC-NR ][ 595.4] Handling MAC PDU (7 B)
025-01-09T19:06:09.165872 [UE-MAC-NR ][ 595.4] DL CON_RES: id=159207be946
2025-01-09T19:06:09.165873 [UE-MAC-NR ][ 595.4] Handling subPDU 1/1: rnti=0x0 lcid=62, sdu_len=6
2025-01-09T19:06:09.165873 [UE-MAC-NR ][ 595.4] Received Contention Resolution ID 0x1509207be946
2025-01-09T19:06:09.165874 [UE-MAC-NR ][ 595.4] Received CONRES ID matches transmitted UE ID
2025-01-09T19:06:09.165892 [UE-MAC-NR ][ 595.4] Random Access Complete.     c-rnti=0x4601, ta=4
2025-01-09T19:06:09.165893 [UE-RRC-NR ]RA completed.

The UE MAC layer decodes the Transport Block from TTI 595.4 and sends the PDU to be disassembled and demultiplexed

MAC layer extracts the Contention Resolution Identity from subPDU 1 of 1 (LCID=62)
- The CR ID matches the ue-Identity sent in the RRC Setup Request message
MAC layer determines that Random Access is complete
RRC layer determines that Random Access is complete

Random Access Message 4 (RRC Setup)

2025-01-09T19:06:09.161018 [RRC     ] [D] ue=0 c-rnti=0x4601: Creating SRB1
2025-01-09T19:06:09.161061 [PDCP    ] [I] ue=0 SRB1 DL: PDCP configured. rb_type=SRB rlc_mode=AM sn_size=12 discard_timer={na} count_notify=3221225472 count_max=4294967294 warn_on_drop=false test_mode=false
2025-01-09T19:06:09.161375 [PDCP    ] [I] ue=0 SRB1 UL: PDCP configured. rb_type=SRB rlc_mode=AM sn_size=12 t_reordering=infinity count_notify=3221225472 count_max=4294967294
2025-01-09T19:06:09.161642 [RRC     ] [D] ue=0 c-rnti=0x4601: Tx CCCH DL rrcSetup (295 B)
2025-01-09T19:06:09.161645 [RRC     ] [D] ue=0 c-rnti=0x4601: TX SRB0 PDU
2025-01-09T19:06:09.161926 [RLC     ]du=0 ue=0 SRB0 DL: TX SDU. sdu_len=295 queued_sdus=1 queued_bytes=295
2025-01-09T19:06:09.161926 [RLC     ]du=0 ue=0 SRB0 DL: Triggering buffer state update to lower layer
2025-01-09T19:06:09.161937 [RLC     ]du=0 ue=0 SRB0 DL: Sending buffer state update to lower layer. bs=295
2025-01-09T19:06:09.162247 [SCHED   ][   595.6] Processed slot events pci=99:
	- RLC Buffer State: ue=0 lcid=0 pending_bytes=295

The gNB RRC layer creates SRB1 that will be configured for the UE in the RRC Setup message. SRB1 begins the inclusion of the PDCP layer, so the PDCP configures for the UL and DL using SRB1.

RRC Layer uses the DL CCCH and SRB0 to pass the RRC Setup message to lower layers.
RLC receives the message and queues the 295 byte data. It will need a MAC opportunity to send to lower layers.
RLC sends a buffer state message that is processed at the MAC scheduler.
MAC layer now knows that there is 295 bytes pending from the RLC layer.

2025-01-09T19:06:09.162256 [SCHED   ][   595.6] Slot decisions pci=99 t=34us (1 PDSCH, 0 PUSCHs):
	- DL PDCCH: rnti=0x4601 type=c-rnti cs_id=0 ss_id=1 format=1_0 cce=0 al=4  dci: h_id=1 ndi=1 rv=0 mcs=0 res_ind=0
	- UE PDSCH: ue=0 c-rnti=0x4601 h_id=1 rb=[0..82) symb=[1..14) tbs=301 mcs=0 rv=0 nrtx=0 k1=4 dl_bo=0 olla=0.00 grants: lcid=0: size=298
2025-01-09T19:06:09.162267 [FAPI    ][   595.6] DL_TTI.request slot=595.6, is_last_message_in_slot=false
	- PDCCH bwp=2:96 symb=0:1 nof_dcis=1
	- PDSCH rnti=0x4601 bwp=2:96 symb=1:13 CW: tbs=301 mod=2 rv_idx=0
2025-01-09T19:06:09.162290 [RLC     ]du=0 ue=0 SRB0 DL: MAC opportunity. grant_len=298
2025-01-09T19:06:09.162291 [RLC     ]du=0 ue=0 SRB0 DL: Read SDU. pdcp_sn={na} sdu_len=295
2025-01-09T19:06:09.162292 [RLC     ]du=0 ue=0 SRB0 DL: TX PDU. pdu_len=295 grant_len=298
2025-01-09T19:06:09.162295 [RLC     ]du=0 ue=0 SRB0 DL: MAC opportunity. grant_len=1
2025-01-09T19:06:09.162296 [RLC     ]du=0 ue=0 SRB0 DL: SDU queue empty. grant_len=1
2025-01-09T19:06:09.162296 [MAC     ][   595.6] ue=0 rnti=0x4601 lcid=0: Unable to encode MAC SDU in MAC opportunity of size=1.
2025-01-09T19:06:09.162298 [MAC     ][   595.6] DL PDU: ue=0 rnti=0x4601 size=301: SDU: lcid=0 nof_sdus=1 total_size=298
2025-01-09T19:06:09.162299 [FAPI    ][   595.6] Tx_Data.request slot=595.6 nof_pdus=1
2025-01-09T19:06:09.162340 [PHY     ][   595.6] PDCCH: rnti=0x4601 ss_id=1 format=1_0 cce=0 al=4 t=40.3us
2025-01-09T19:06:09.162475 [PHY     ][   595.6] PDSCH: rnti=0x4601 h_id=1 k1=4 prb=[0, 82) symb=[1, 14) mod=QPSK rv=0 tbs=301
2025-01-09T19:06:09.163303 [SCHED   ][   595.7] Processed slot events pci=99:
	- RLC Buffer State: ue=0 lcid=0 pending_bytes=0

The gNB schedules the resource allocation and transmission of the RRC Setup message. Observe that the PDCCH DCI 1_0 is now using type=c-rnti opposed to the previous transmission using the tc-rnti, which in this case is the same as the TC-RNTI.

FAPI requests DL TTI of 595.6 for PDCCH DCI 1_0 and PDSCH
RLC layer that had previously queued the RRC Setup message receives a MAC opportunity to pass the data to the MAC layer on
- Once the data is passed the queue is empty
MAC layer adds SDU with LCID 0
FAPI indicates a data transfer request on TTI 595.6
PDCCH DCI 1_0 with PDSCH resource allocation is transmitted
PDSCH with RRC Setup message with TBS of 301 bytes is transmitted
The RLC buffer state indicates that it is empty by providing a buffer state of 0 pending bytes

2025-01-09T19:06:09.167385 [UE-PHY_LIB][    0]  PDCCH Rx: K=65; E=432; M=216; n=9;
2025-01-09T19:06:09.167401 [UE-PHY_LIB][    0]  Found DCI in L=2,ncce=0
2025-01-09T19:06:09.167454 [UE-PHY2-NR][ 595.6] PDCCH: cc=0, c-rnti=0x4601 dci=1_0 ss=common0 L=2 cce=0 f_alloc=0x5ff t_alloc=0x0 vrb_to_prb_map=0 mcs=0 ndi=1 rv=0 harq_id=1 dai=0 pucch_tpc=1 pucch_res=0 harq_feedback=3 
2025-01-09T19:06:09.167478 [UE-PHY_LIB][    0]  LDPC CB Segmentation: TBS: 2408, C=1, K=2560, F=2560, Bp=2424
2025-01-09T19:06:09.167485 [UE-PHY2-NR][ 595.6] PDCCH: c-rnti=0x4601 dci=0_0 ss=common3 L=2 cce=0 EPRE=+9.59, RSRP=+9.15, corr=0.904 nof_bits=41 crc=OK
2025-01-09T19:06:09.167486 [UE-MAC-NR ][ 595.6] new_grant_dl(): cc_idx=0, tti=5956, rnti=17921, pid=1, tbs=301, ndi=1, rv=
2025-01-09T19:06:09.167673 [UE-PHY_LIB][    0]  PDSCH: RNTI=17921 (0x4601); nid=99; cinit=587235427 (0x23008063);
2025-01-09T19:06:09.167683 [UE-PHY_LIB][    0]  SCH Rx: RM CB 0: E=19680; F=136; BG=2; Z=256; RV=0; Qm=2; Nref=25344;
2025-01-09T19:06:09.167998 [UE-PHY_LIB][    0]  SCH Rx: CB 0/1 iter=1 CRC=OK
2025-01-09T19:06:09.168000 [UE-PHY_LIB][    0]  SCH Rx: TB: TBS=2408; CRC=OK
2025-01-09T19:06:09.168021 [UE-PHY2-NR][ 595.6] PDSCH: cc=0 pid=1 c-rnti=0x4601 prb=(2,83) symb=(1,13) CW0: mod=QPSK tbs=301 R=0.123 rv=0 CRC=OK

The UE detects PDCCH 1_0 and receives resource allocation (new_grant_dl @ TTI 595.6) for the PDSCH with the RRC Setup message. The UE receives the PDSCH with TBS of 301 bytes. Observe that harq_id=1 is associated with PDCCH for RRC Setup.

UE also attempts to detect PDCCH DCI 0_0 for PUSCH transmission resource allocation
DCI 0_0 was not sent by the gNB yet.

2025-01-09T19:06:09.168023 [UE-MAC-NR ][ 595.6] tb_decoded(): cc_idx=0, tti=5956, rnti=0x4601, pid=1, tbs=301, ndi=1, rv=0, result=OK
2025-01-09T19:06:09.168030 [UE-MAC-NR ][ 595.6] Delivering PDU=301 bytes to Dissassemble and Demux unit
2025-01-09T19:06:09.168117 [UE-MAC-NR ][ 595.7] Handling MAC PDU (301 B)
2025-01-09T19:06:09.168123 [UE-MAC-NR ][ 595.7] DL LCID=0 len=295 PAD: len=2
2025-01-09T19:06:09.168123 [UE-MAC-NR ][ 595.7] Handling subPDU 1/2: rnti=0x0 lcid=0, sdu_len=295
2025-01-09T19:06:09.168125 [UE-RRC-NR ]RX PDU, LCID: 0
2025-01-09T19:06:09.168206 [UE-RRC-NR ]SRB0 - Rx rrcSetup (295 B)
2025-01-09T19:06:09.168216 [UE-MAC-NR ][ 595.7] Handling subPDU 2/2: rnti=0x0 lcid=63, sdu_len=2
2025-01-09T19:06:09.168537 [UE-RRC-NR ]Containerized MasterCellGroup: {
2025-01-09T19:06:09.168547 [UE-RRC-NR ]Proc "Connection Setup" - Starting...
2025-01-09T19:06:09.168608 [UE-RLC-NR ]SRB1: RLC AM NR configured rx entity.
2025-01-09T19:06:09.168670 [UE-RLC-NR ]SRB1: AM NR configured - tx_sn_field_length=12, rx_sn_field_length=12, t_poll_retx=45, poll_pdu=-1, poll_byte=-1, max_retx_thresh=8, t_reassembly=35, t_status_prohibit=0, tx_queue_length=256
2025-01-09T19:06:09.168674 [UE-RLC-NR ]Added NR radio bearer with LCID 1 in Acknowledged Mode
2025-01-09T19:06:09.168678 [UE-MAC-NR ][ 595.7] Logical Channel Setup: LCID=1, LCG=0, priority=1, PBR=-1, BSD=5ms, bucket_size=-5
2025-01-09T19:06:09.168680 [UE-MAC-NR ][ 595.7] SR:    Set sr-TransMax=64
2025-01-09T19:06:09.168681 [UE-RRC-NR ]Handling MAC BSR config
2025-01-09T19:06:09.168682 [UE-MAC-NR ][ 595.7] BSR:   Configured timer periodic 10 ms
2025-01-09T19:06:09.168683 [UE-MAC-NR ][ 595.7] BSR:   Configured timer reTX 80 ms
2025-01-09T19:06:09.168683 [UE-MAC-NR ][ 595.7] Add tag config not supported yet
2025-01-09T19:06:09.168684 [UE-MAC-NR ][ 595.7] Add phr config not supported yet
2025-01-09T19:06:09.168688 [UE-RRC-NR ]Reconfig with sync not present

The PHY layer passed the transport block to the MAC layer where the TB is decoded.

MAC layer disassembles and demultiplexes the data into two subPDUs
- subPDU 1/2 LCID=0 for CCCH
- subPDU 2/2 LCID=63 for Padding
subPDU 1/2 on CCCH goes to the RRC layer, where the RRC Setup message is extracted
RRC Layer extracts the MasterCellGroup container from the RRC Setup message
- RRC Connection setup begins
RLC Acknowledged Mode Tx/Rx entities are configured at the UE using the rlc-Config: am parameters specified in the RRC Setup message

MAC configured Logical Channel Setup using the mac-LogicalChannelConfig parameters specified in the RRC Setup message

MAC Scheduling Request (SR), Buffer Status Report (BSR), Timing Advance (TAG), and Power Headroom (PHR) are configured from RRC Setup message parameters as well.

The rest of the RRC Setup message is processed later.

HARQ Attempt

Now that the UE has receives Contention Resolution and RRC Setup, it must acknowledge the receipt of that data with the gNB by sending HARQ ACKs for each.

2025-01-09T19:06:09.164095 [SCHED   ][   595.8] Slot decisions pci=99 t=17us (0 PDSCHs, 0 PUSCHs):
	- PUCCH: c-rnti=0x4601 format=1 prb=[0..1) second_prbs=[105..106) symb=[0..14) cs=0 occ=0 uci: harq_bits=1 sr=0
2025-01-09T19:06:09.164136 [FAPI    ][   595.8] UL_TTI.request slot=595.8
	- PUCCH rnti=0x4601 bwp=0:106 format=1 prb=0:1 prb2=105 symb=0:14 harq_bit_len=1 sr_bit_len=0
2025-01-09T19:06:09.166077 [SCHED   ][   596.0] Slot decisions pci=99 t=10us (0 PDSCHs, 0 PUSCHs):
	- PUCCH: c-rnti=0x4601 format=1 prb=[4..5) symb=[0..14) cs=0 occ=0 uci: harq_bits=0 sr=1
	- PUCCH: c-rnti=0x4601 format=1 prb=[0..1) second_prbs=[105..106) symb=[0..14) cs=0 occ=0 uci: harq_bits=1 sr=0
2025-01-09T19:06:09.166119 [FAPI    ][   596.0] UL_TTI.request slot=596.0
	- PUCCH rnti=0x4601 bwp=0:106 format=1 prb=4:1 prb2=0 symb=0:14 harq_bit_len=0 sr_bit_len=1
	- PUCCH rnti=0x4601 bwp=0:106 format=1 prb=0:1 prb2=105 symb=0:14 harq_bit_len=1 sr_bit_len=0

FAPI Requests UL TTI 595.8
FAPI Requests UL TTI 596.0 (which is also looking for a PDCCH with a scheduling request)

2025-01-09T19:06:09.165894 [UE-MAC-NR ][ 595.4] DL 0:  newTX tbs=7, rv=0, ack=OK, ndi=1
2025-01-09T19:06:09.165898 [UE-PHY0-NR][ 595.4] use_pusch=n nof_cc=1
  CC 0: M=1
    m 0: k1=4 dai=0 ack=1
2025-01-09T19:06:09.165931 [UE-PHY_LIB][    0]  [UE-PUCCH Format 1 Data TX] d=-0.707-0.707
2025-01-09T19:06:09.166111 [UE-PHY0-NR][ 595.4] PUCCH: cc=0, f=1 prb=0:1 symb=0:14 cs=0 occ=0 rnti=0x4601 ack=1 , tti_tx=5958

While processing the Contention Resolution message, the UE MAC extracts DL 0 associated with tbs=7 that requires acknowledgement (ack=OK)

use_pusch=n: the UE will not use the PUSCH to transmit ack=1
UE will transmit PUCCH with Format 1
The UE transmits HARQ ack=1 at TTI 595.8
- calculated using k1 value (k1=4) from the TTI that PDCCH with harq_feedback was received (595.4 +.4 = 595.8)

2025-01-09T19:06:09.168032 [UE-MAC-NR ][ 595.6] DL 1:  newTX tbs=301, rv=0, ack=OK, ndi=1
2025-01-09T19:06:09.168039 [UE-PHY2-NR][ 595.6] use_pusch=n nof_cc=1
  CC 0: M=1
    m 0: k1=4 dai=0 ack=1
2025-01-09T19:06:09.168081 [UE-PHY_LIB][    0]  [UE-PUCCH Format 1 Data TX] d=-0.707-0.707
2025-01-09T19:06:09.168357 [UE-PHY2-NR][ 595.6] PUCCH: cc=0, f=1 prb=0:1 symb=0:14 cs=0 occ=0 rnti=0x4601 ack=1 , tti_tx=5960

While processing the RRC Setup message, the UE MAC extracts DL 1 associated with tbs=301 that requires acknowledgement (ack=OK)

use_pusch=n: the UE will not use the PUSCH to transmit ack=1
UE will transmit PUCCH with Format 1
The UE transmits HARQ ack=1 at TTI 596.0
- calculated using k1 value (k1=4) from the TTI that PDCCH with harq_feedback was received (595.6 +.4 = 596.0)

2025-01-09T19:06:09.169404 [PHY     ][   595.8] PUCCH: rnti=0x4601 format=1 prb1=0 prb2=105 symb=[0, 14) cs=0 occ=0 ack=2
2025-01-09T19:06:09.169500 [FAPI    ][   596.3] UCI.indication slot=595.8
2025-01-09T19:06:09.169500	- UCI PUCCH format 0/1 format=1 rnti=17921 sinr=26.7 HARQ: confidence=255 harq_ack=dtx
2025-01-09T19:06:09.170140 [SCHED   ][   596.4] rnti=0x4601: PUCCH PDU allocated on F1 HARQ resource: slot=596.8 p_ind=0 prbs=[0..1) sym=[0..14) cs=0 occ=0 h_bits=1 sr_bits=0
2025-01-09T19:06:09.170145 [SCHED   ][   596.4] rnti=0x4601: PUCCH on common and ded. resource with res_ind=0 allocated for slot=596.8
2025-01-09T19:06:09.170156 [SCHED   ][   596.4] Processed slot events pci=99:
2025-01-09T19:06:09.170156- HARQ-ACK: ue=0 rnti=0x4601 pci=99 slot_rx=595.8 h_id=0 ack=2

Here is where we encounter our first “problem”

gNB receives PUCCH with HARQ for Contention Resolution with ack=2
- FAPI: UCI PUCCH: indicates harq_ack=dtx
The HARQ is processed as not being acknowledged

2025-01-09T19:06:09.171283 [PHY     ][   596.0] PUCCH: rnti=0x4601 format=1 prb1=0 prb2=105 symb=[0, 14) cs=0 occ=0 ack=2
2025-01-09T19:06:09.171291 [PHY     ][   596.0] PUCCH: rnti=0x4601 format=1 prb1=4 prb2=na symb=[0, 14) cs=0 occ=0 sr=no
2025-01-09T19:06:09.171294 [FAPI    ][   596.4] UCI.indication slot=596.0
	- UCI PUCCH format 0/1 format=1 rnti=17921 sinr=26.6 HARQ: confidence=255 harq_ack=dtx
2025-01-09T19:06:09.171353 [FAPI    ][   596.4] UCI.indication slot=596.0
	- UCI PUCCH format 0/1 format=1 rnti=17921 sinr=-20.1 SR: confidence=255 sr=not detected
2025-01-09T19:06:09.171476 [SCHED   ][   596.5] rnti=0x4601: PUCCH PDU allocated on F1 HARQ resource: slot=596.9 p_ind=0 prbs=[0..1) sym=[0..14) cs=0 occ=0 h_bits=1 sr_bits=0
2025-01-09T19:06:09.171478 [SCHED   ][   596.5] rnti=0x4601: PUCCH on common and ded. resource with res_ind=0 allocated for slot=596.9
2025-01-09T19:06:09.171492 [SCHED   ][   596.5] Processed slot events pci=99:
- HARQ-ACK: ue=0 rnti=0x4601 pci=99 slot_rx=596.0 h_id=1 ack=2

gNB receives PUCCH with HARQ for RRC Setup with ack=2
gNB attempts to receive PUCCH with SR though the UE has not transmitted a PUCCH with Scheduling Request
- FAPI: UCI PUCCH: indicates harq_ack=dtx
- FAPI: UCI PUCCH: indicates sr=not detected
  - Observe the comparison of SINR between the HARQ and SR. (HARQ = 26.6, SR = -20.1)
    - Suggests that the SR was not sent
The HARQ is processed as not being acknowledged

As we see later on in this analysis, further scheduling may have caused these PUCCH transmissions to become invalid when they are received in the wrong TTI.

CR HARQ ACK
- Scheduled for UL TTI 595.8
- Transmitted on TTI 595.8
  - PUCCH on common and ded. resource with res_ind=0 allocated for slot=596.8
RRC Setup HARQ ACK
- Scheduled for UL TTI 596.0
- Transmitted on TTI 596.0
PUCCH on common and ded. resource with res_ind=0 allocated for slot=596.9

Part 2

In the next part of this blog we will analyze

CR and RRC Setup Retransmission
HARQ Retransmission
RRC Setup Complet & Registration Request
and more

srsRAN CU/DU and srsUE Control Plane Log Analysis Part 1

Introduction

gNB CU Config

gNB DU Config

srsUE Config

SRS Logs

SRS Log Control Plane Protocols

MIB

SIB1

Prepare RRC Setup Request

Random Access Message 1 (Preamble)

Random Access Message 2 (Random Access Response)

Random Access Message 3 (Scheduled Transmission/RRC Setup Request)

Random Access Message 4 (Contention Resolution)

Random Access Message 4 (RRC Setup)

HARQ Attempt

Part 2

Like this:

Leave a ReplyCancel reply

srsRAN CU/DU and srsUE Control Plane Log Analysis Part 1

Introduction

gNB CU Config

gNB DU Config

srsUE Config

SRS Logs

SRS Log Control Plane Protocols

MIB

SIB1

Prepare RRC Setup Request

Random Access Message 1 (Preamble)

Random Access Message 2 (Random Access Response)

Random Access Message 3 (Scheduled Transmission/RRC Setup Request)

Random Access Message 4 (Contention Resolution)

Random Access Message 4 (RRC Setup)

HARQ Attempt

Part 2

Share this:

Like this:

Leave a ReplyCancel reply

Discover more from