Large delay and CRC failure in Msg3

[improperaffo]

Dear all,
I am experimenting adding artificial delay at the physical layer between a SRS gNB and a COTS UE (release <17, so NTN available).

So far, I have been able to add up to 460 microseconds of delay per channel (Rx and Tx), I had to modify the RA procedure to estimate such large timing advance (around 924.70 microseconds).
Any number higher than 924.70 microsecond results in a False CRC of Msg3 of the RA procedure. I have tried tracing this error back, but I was unsuccessful.

Does anyone know about anything that can be tuned, or a parameter that can be set?

Here is the configuration I have been using.

Thanks in advance.

[dvdgrgrtt]

Hi @improperaffo,
I'd start by checking that the timing advance is reported correctly in Msg2. With those delays, if the UE doesn't adjust its transmission timing, you can easily end up outside the cyclic prefix and, in turn, the channel estimator and equalizer will not be able to do their job.

With the PHY and MAC logs in debug you should see lines like

2025-05-07T14:36:40.090139 [PHY     ] [D] [  496.18] PRACH: rsi=1 rssi=-64.6dB detected_preambles=[{idx=62 ta=0.00us detection_metric=173.0}] t=162.9us
  rsi=1
  preambles=[0, 64)
  format=0
  set=unrestricted
  zcz=0
  scs=30kHz
  nof_rx_ports=1
  rssi=-64.6dB
  res=0.8us
  max_ta=81.88us
  detected_preambles=[{idx=62 ta=0.00us detection_metric=173.0}]

2025-05-07T14:36:40.090529 [SCHED   ] [D] [   497.5] Processed slot events pci=1:
- PRACH: slot=496.18 pci=1 preamble=62 ra-rnti=0x7f temp_crnti=0x4601 ta_cmd=0
2025-05-07T14:36:40.093023 [SCHED   ] [D] [  497.10] Slot decisions pci=1 t=5us (1 PDSCH, 0 PUSCHs, 0 attempted PDCCHs, 0 attempted UCIs):
- DL PDCCH: rnti=0x7f type=ra-rnti cs_id=0 ss_id=1 format=1_0 cce=0 al=4 
- RAR PDSCH: ra-rnti=0x7f rb=[0..3) symb=[1..14) tbs=10 mcs=0 rv=0 grants (1): tc-rnti=0x4601: rapid=62 ta=0 time_res=0

Check that values reported by the PRACH detector (ta=X.XXus) and that the TA command (ta_cmd, an integer between 0 and 3846) are consistent with each other and with the delay you're simulating.

[improperaffo]

Hi @dvdgrgrtt , thanks for your answer.

Here is what I get in my logs when Msg3 CRC fails (above 924.70 us):

2025-07-24T15:44:08.513563 [PHY     ] [D] [   353.9] PRACH: rsi=0 rssi=-11.6dB detected_preambles=[{idx=0 ta=928.12us detection_metric=11.3}] t=413.1us
  rsi=0
  preambles=[0, 64)
  format=1
  set=unrestricted
  zcz=0
  scs=15kHz
  nof_rx_ports=1
  rssi=-11.6dB
  res=0.8us
  max_ta=546.88us
  detected_preambles=[{idx=0 ta=928.12us detection_metric=11.3}]

2025-07-24T15:44:08.513570 [FAPI    ] [D] [   354.5] Sector#0: RACH.indication slot=353.9
        - PRACH symb_idx=0 slot_idx=9 rssi=-11.6 nof_preambles=1:
                - PREAMBLE index=0 ta_ns=928125 pwr=10.5 snr=10.5
2025-07-24T15:44:08.514053 [FAPI    ] [D] [   354.6] Sector#0: Slot.indication time_point=1753371848515053153
2025-07-24T15:44:08.514075 [SCHED   ] [D] [   354.6] Processed slot events pci=1:
- PRACH: slot=353.9 pci=1 preamble=0 ra-rnti=0x7f temp_crnti=0x4602 ta_cmd=1782
2025-07-24T15:44:08.514080 [SCHED   ] [D] [   354.6] Slot decisions pci=1 t=16us (1 PDSCH, 0 PUSCHs, 0 attempted PDCCHs, 0 attempted UCIs):
- DL PDCCH: rnti=0x7f type=ra-rnti cs_id=0 ss_id=1 format=1_0 cce=0 al=4 
- RAR PDSCH: ra-rnti=0x7f rb=[0..3) symb=[2..14) tbs=9 mcs=0 rv=0 grants (1): tc-rnti=0x4602: rapid=0 ta=1782 time_res=0

And here is what I get when it succeeds:

2025-07-24T15:55:32.074043 [PHY     ] [D] [   433.9] PRACH: rsi=0 rssi=-20.3dB detected_preambles=[{idx=48 ta=924.22us detection_metric=1.9}] t=381.3us
  rsi=0
  preambles=[0, 64)
  format=1
  set=unrestricted
  zcz=0
  scs=15kHz
  nof_rx_ports=1
  rssi=-20.3dB
  res=0.8us
  max_ta=546.88us
  detected_preambles=[{idx=48 ta=924.22us detection_metric=1.9}]

2025-07-24T15:55:32.074052 [FAPI    ] [D] [   434.5] Sector#0: RACH.indication slot=433.9
        - PRACH symb_idx=0 slot_idx=9 rssi=-20.3 nof_preambles=1:
                - PREAMBLE index=48 ta_ns=924218 pwr=2.8 snr=2.5
2025-07-24T15:55:32.074597 [FAPI    ] [D] [   434.6] Sector#0: Slot.indication time_point=1753372532075596754
2025-07-24T15:55:32.074645 [SCHED   ] [D] [   434.6] Processed slot events pci=1:
- PRACH: slot=433.9 pci=1 preamble=48 ra-rnti=0x7f temp_crnti=0x4601 ta_cmd=1774
2025-07-24T15:55:32.074666 [SCHED   ] [D] [   434.6] Slot decisions pci=1 t=24us (1 PDSCH, 0 PUSCHs, 0 attempted PDCCHs, 0 attempted UCIs):
- DL PDCCH: rnti=0x7f type=ra-rnti cs_id=0 ss_id=1 format=1_0 cce=0 al=4 
- RAR PDSCH: ra-rnti=0x7f rb=[0..3) symb=[2..14) tbs=9 mcs=0 rv=0 grants (1): tc-rnti=0x4601: rapid=48 ta=1774 time_res=0

It seems to me that they are consinstent.

[dvdgrgrtt]

I'm a bit worried about ta being larger than ta_max in the PRACH log. But if the measured TA makes sense with your set-up, I guess we can ignore this for now. And the TA command in Msg2 is consistent with the PRACH TA, yes.

You're using a COTS UE, right? So I guess we don't have logs at the UE side, or anything else we can use to check whether the UE received this correctly and reacted to it as expected.

By the way, how are you adding the delay?

[improperaffo]

Yes, the measured TA reflects the artificial delay I am adding.

Yes, I am using a COTS UE, so no log from the UE side, but different COTS UEs fail at the same amount of delay, so I am excluding UE-related issues.

I am adding the delay by tinkering with the metadata of the samples as they are sent to the radio and as they are received from the radio. I am effectively adding an offset to the metadata timestamp.

[improperaffo]

I added some log messages and I tested some more, it seems that there are some issues related to the LDPC decoding (looking at the first 10 LLRs).

Successful attempt (less than 924.70 us):

Detected PRACH preamble delay=159 with peak=1.0416207 and threshold=0.61. Time advance: 924.22 us
Timing_advance_offset_ns = 924218 and success true
Validated RACH indication message in slot=209.9 with 1 preambles
RARs scheduled in slot 210.6: nof_allocs=1
PUSCH_DEMOD: Processing symbol 0/13 (range: 0-13)
=== PUSCH DEMODULATION SYMBOL 0 ANALYSIS ===
Active REs in symbol: 36, Total layers: 1
Noise variances: Port 0: 0.045750 
POST-EQUALIZATION: Avg power: 0.998925, Avg noise: 0.009445, SNR: 20.24 dB
DEMOD LLR QUALITY: Mean |LLR|: 120.0000, Std dev: 0.0000, Strong bits: 100.00%, Weak bits: 0.00%
WARNING: LLR SATURATION DETECTED! 100.0% of bits are saturated (>=119) - this may cause false decode success
This often indicates timing/synchronization issues causing artificial high SNR
WARNING: Uniform high-magnitude LLRs detected (std_dev=0.00, mean=120.00) - likely signal processing artifact
PUSCH_DEMOD: Processing symbol 1/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 2/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 3/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 4/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 5/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 6/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 7/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 8/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 9/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 10/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 11/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 12/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 13/13 (range: 0-13)
Input_size=868 and message_length=180
First 10 LLRs: -120.00 120.00 -120.00 120.00 120.00 120.00 -120.00 120.00 120.00 -120.00 
Last 10 LLRs: 120.00 120.00 120.00 120.00 120.00 120.00 120.00 -120.00 120.00 120.00 
LLR Quality: mean_abs=120.61, std_dev=1.98, min=120.00, max=127.00, strong_bits=868, weak_bits=0, zero_bits=0
LLR Ratios: strong=100.00%, weak=0.00%, zero=0.00%
LDPC Decoder: Starting with 41 layers, 6 iterations max
LDPC WARNING: 100.0% of LLRs are saturated (>=120) - high risk of false positive!
This typically indicates timing/synchronization issues causing artificial confidence
LDPC WARNING: Nearly uniform high-magnitude LLRs detected - decoder may produce false positive
LDPC WARNING: Decoder converged in just 1 iteration - this may be a false positive!
Single-iteration convergence often indicates saturated LLR inputs
LDPC: Successfully decoded after 1 iterations (early stop), CRC=0x0
MSG3: MSG3 successfully decoded for rnti=0x4602 - forwarding to upper layers
MSG4: RRC Setup sent to UE 0, waiting for RRC Setup Complete (timeout=12800ms)

Unsuccessful attempt:

Detected PRACH preamble delay=164 with peak=7.894962 and threshold=0.61. Time advance: 928.12 us
Timing_advance_offset_ns = 928125 and success true
Validated RACH indication message in slot=529.9 with 1 preambles
RARs scheduled in slot 530.6: nof_allocs=1
PUSCH_DEMOD: Processing symbol 0/13 (range: 0-13)
=== PUSCH DEMODULATION SYMBOL 0 ANALYSIS ===
Active REs in symbol: 36, Total layers: 1
Noise variances: Port 0: 0.000875 
POST-EQUALIZATION: Avg power: 14.617847, Avg noise: 13.305868, SNR: 0.41 dB
DEMOD LLR QUALITY: Mean |LLR|: 3.1944, Std dev: 2.7164, Strong bits: 47.22%, Weak bits: 12.50%
PUSCH_DEMOD: Processing symbol 1/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 2/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 3/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 4/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 5/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 6/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 7/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 8/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 9/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 10/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 11/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 12/13 (range: 0-13)
PUSCH_DEMOD: Processing symbol 13/13 (range: 0-13)
Input_size=868 and message_length=180
First 10 LLRs: -2.00 -1.00 0.00 -2.00 -1.00 2.00 -3.00 -2.00 -2.00 -2.00 
Last 10 LLRs: 120.00 120.00 -120.00 120.00 120.00 -120.00 120.00 -120.00 120.00 120.00 
LLR Quality: mean_abs=22.88, std_dev=45.62, min=0.00, max=127.00, strong_bits=154, weak_bits=342, zero_bits=149
LLR Ratios: strong=17.74%, weak=39.40%, zero=17.17%
WARNING: High number of zero LLRs (17.17%) - possible input corruption
LDPC Decoder: Starting with 41 layers, 6 iterations max
LDPC: Iteration 2/6, CRC=0x8EFF, hard_bits_success=false
LDPC: Iteration 4/6, CRC=0x44E7, hard_bits_success=false
LDPC: Iteration 6/6, CRC=0xDCF0, hard_bits_success=false
LDPC: Failed to decode codeblock after 6 iterations.
Final state: hard_bits_success=false, CRC=0xDCF0, significant_bits=104
First 32 decoded bits: 00110111000100101110110101001001
MSG3: MSG3 CRC FAILED for rnti=0x4605 - will schedule retransmission

[dvdgrgrtt]

For me the weak LLRs are just a symptom of something wrong going on with the channel estimation / equalization. See how the POST-EQUALIZATION SNR dropped from the successful to the unsuccessful case?

Can you share also the gNB logs relative to the reception of Msg3?

[improperaffo]

I agree with you.

I could not find much regarding Msg3 in the gNB logs, here is the only appearance:

- UE PUSCH: ue=1024 tc-rnti=0x4601 h_id=0 rb=[2..5) symb=[0..14) tbs=11 rv=0 nrtx=0 nof_layers=1 msg3_delay=6

Here are the full gNB logs.

[dvdgrgrtt]

It's the first PUSCH after a detected PRACH. What you found is the message from the scheduler saying that it allocated resources for the PUSCH - a few lines below you'll see something like (this is taken from your logs)

2025-07-25T07:44:21.224417 [PHY     ] [D] [   371.2] PUSCH: rnti=0x4603 h_id=0 prb=[2, 5) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=KO iter=6.0 sinr=-17.3dB t=154.4us uci_t=0.0us ret_t=0.0us
  rnti=0x4603
  h_id=0
  bwp=[0, 106)
  prb=[2, 5)
  symb=[0, 14)
  oack=0
  ocsi1=0
  part2=entries=[]
  alpha=0
  betas=[0, 0, 0]
  mod=QPSK
  tcr=0.1171875
  rv=0
  bg=2
  new_data=true
  n_id=1
  dmrs_mask={2, 7, 11}
  tbs_lbrm=159749bytes
  slot=371.2
  cp=normal
  nof_layers=1
  ports=0
  dc_position=optional(636)
  n_scr_id=1
  n_scid=false
  n_cdm_g_wd=2
  dmrs_type=1
  crc=KO
  iter=6.0
  max_iter=6
  min_iter=6
  nof_cb=1
  sinr_ch_est=-6.7dB
  sinr_eq[sel]=-17.3dB
  sinr_evm=-36.5dB
  evm=[7.44 12.16 na 3.24 3.23 3.36 6.20 na 7.51 3.87 4.11 na 4.90 423.45]
  epre=-41.5dB
  rsrp=-48.8dB
  sinr=-17.3dB
  t_align=-1.36us
  cfo=+1373.5Hz

I'd like to see the entry for a successful detection, too, if possible. BTW, you can probably disable the FAPI logs at this point - they add a lot of clutter and they're not very helpful.

[improperaffo]

Here is the successful attempt.

This should be the first PUSCH after a detected PRACH:

2025-07-25T09:26:08.259630 [PHY     ] [D] [   499.2] PUSCH: rnti=0x4601 h_id=0 prb=[2, 5) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=OK iter=1.0 sinr=31.9dB t=252.8us uci_t=0.0us ret_t=0.0us
  rnti=0x4601
  h_id=0
  bwp=[0, 106)
  prb=[2, 5)
  symb=[0, 14)
  oack=0
  ocsi1=0
  part2=entries=[]
  alpha=0
  betas=[0, 0, 0]
  mod=QPSK
  tcr=0.1171875
  rv=0
  bg=2
  new_data=true
  n_id=1
  dmrs_mask={2, 7, 11}
  tbs_lbrm=159749bytes
  slot=499.2
  cp=normal
  nof_layers=1
  ports=0
  dc_position=optional(636)
  n_scr_id=1
  n_scid=false
  n_cdm_g_wd=2
  dmrs_type=1
  crc=OK
  iter=1.0
  max_iter=1
  min_iter=1
  nof_cb=1
  sinr_ch_est=35.0dB
  sinr_eq[sel]=31.9dB
  sinr_evm=29.5dB
  evm=[0.02 0.02 na 0.02 0.02 0.02 0.02 na 0.02 0.02 0.02 na 0.02 0.02]
  epre=-0.4dB
  rsrp=-0.4dB
  sinr=+31.9dB
  t_align=0.63us
  cfo=-5.0Hz

Full logs.

[dvdgrgrtt]

Mmmm, comparing the EPRE of the two cases, it looks like there's no signal at all in the unsuccessful one. If you have MATLAB available, I'd suggest you try our srsPUSCHAnalyzer (have a look here or here), it can probably provide some insight.