search

srsran / srsRAN_Project

Open source O-RAN 5G CU/DU solution from Software Radio Systems (SRS) https://docs.srsran.com/projects/project
https://www.srsran.com
GNU Affero General Public License v3.0
476 stars 163 forks source link

srsUE can not connect (b210) #154

Closed eulenleber closed 10 months ago

eulenleber commented 1 year ago

Issue Description

gnb is connected to open5g core and "visible" to the client sdr (via spectrum analyzer) but the client sdr can not connect using srsue

Setup Details

Lower PHY in quad executor mode.

--== srsRAN gNB (commit 583c92b16) ==--

Connecting to AMF on 127.0.0.5:38412
Available radio types: uhd.
[INFO] [UHD] linux; Clang version 14.0.0 ; Boost_107400; UHD_4.4.0.0-68-g02558b69
[INFO] [LOGGING] Fastpath logging disabled at runtime.
Making USRP object with args 'type=b200,num_recv_frames=64,num_send_frames=64'
[INFO] [B200] Detected Device: B210
[INFO] [B200] Operating over USB 3.
[INFO] [B200] Initialize CODEC control...
[INFO] [B200] Initialize Radio control...
[INFO] [B200] Performing register loopback test...
[INFO] [B200] Register loopback test passed
[INFO] [B200] Performing register loopback test...
[INFO] [B200] Register loopback test passed
[INFO] [B200] Setting master clock rate selection to 'automatic'.
[INFO] [B200] Asking for clock rate 16.000000 MHz...
[INFO] [B200] Actually got clock rate 16.000000 MHz.
[INFO] [MULTI_USRP] Setting master clock rate selection to 'manual'.
[INFO] [B200] Asking for clock rate 11.520000 MHz...
[INFO] [B200] Actually got clock rate 11.520000 MHz.
Cell pci=1, bw=10 MHz, dl_arfcn=368500 (n3), dl_freq=1842.5 MHz, dl_ssb_arfcn=368410, ul_freq=1747.5 MHz

==== gNodeB started ===
Type <t> to view trace

tail -f gnb.log

...
2023-07-31T16:07:59.494512 [SCHED   ] [I] [   871.2] UL HARQ rnti=0x4605 cell=0 h_id=0: Discarding HARQ with tbs=11. Cause: Maximum number of reTxs 4 exceeded
2023-07-31T16:07:59.601758 [UL-PHY0 ] [I] [   881.4] PRACH:  rssi=+3.7dB detected_preambles=[{idx=0 ta=11.72us power=-5.0dB snr=-5.0dB}] t=260.7us
2023-07-31T16:07:59.602428 [SCHED   ] [I] [   882.0] Slot decisions cell=0 t=16us: RAR: ra-rnti=0x39 rb=[0..3) tbs=9
2023-07-31T16:07:59.602530 [DL-PHY4 ] [I] [   882.0] PDCCH: rnti=0x0039 ss_id=1 format=1_0 cce=0 al=4 t=35.4us
2023-07-31T16:07:59.602549 [DL-PHY4 ] [I] [   882.0] PDSCH: rnti=0x0039 prb=[0, 3) symb=[2, 14) mod=QPSK rv=0 tbs=9 t=17.4us
2023-07-31T16:07:59.608558 [SCHED   ] [I] [   882.6] Slot decisions cell=0 t=6us: UL: ue=1024 rnti=0x4606 h_id=0 ss_id=1 rb=[4..7) k2=0 rv=0 tbs=11
2023-07-31T16:07:59.613773 [UL-PHY2 ] [I] [   882.6] PUSCH: rnti=0x4606 h_id=0 prb=[4, 7) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=KO iter=6.0 snr=-16.2dB t=263.9us
2023-07-31T16:07:59.614555 [DL-PHY0 ] [I] [   883.2] PDCCH: rnti=0x4606 ss_id=1 format=0_0 cce=0 al=4 t=29.1us
2023-07-31T16:07:59.618482 [SCHED   ] [I] [   883.6] Slot decisions cell=0 t=6us: UL: ue=1024 rnti=0x4606 h_id=0 ss_id=1 rb=[4..7) k2=4 rv=0 tbs=11
2023-07-31T16:07:59.623699 [UL-PHY3 ] [I] [   883.6] PUSCH: rnti=0x4606 h_id=0 prb=[4, 7) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=KO iter=6.0 snr=-21.0dB t=270.6us
2023-07-31T16:07:59.624462 [DL-PHY2 ] [I] [   884.2] PDCCH: rnti=0x4606 ss_id=1 format=0_0 cce=0 al=4 t=28.5us
2023-07-31T16:07:59.628401 [SCHED   ] [I] [   884.6] Slot decisions cell=0 t=5us: UL: ue=1024 rnti=0x4606 h_id=0 ss_id=1 rb=[4..7) k2=4 rv=0 tbs=11
2023-07-31T16:07:59.633850 [UL-PHY4 ] [I] [   884.6] PUSCH: rnti=0x4606 h_id=0 prb=[4, 7) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=KO iter=6.0 snr=-22.3dB t=275.6us
2023-07-31T16:07:59.634581 [DL-PHY4 ] [I] [   885.2] PDCCH: rnti=0x4606 ss_id=1 format=0_0 cce=0 al=4 t=32.2us
2023-07-31T16:07:59.638561 [SCHED   ] [I] [   885.6] Slot decisions cell=0 t=6us: UL: ue=1024 rnti=0x4606 h_id=0 ss_id=1 rb=[4..7) k2=4 rv=0 tbs=11
2023-07-31T16:07:59.643753 [UL-PHY1 ] [I] [   885.6] PUSCH: rnti=0x4606 h_id=0 prb=[4, 7) symb=[0, 14) mod=QPSK rv=0 tbs=11 crc=KO iter=6.0 snr=-22.0dB t=261.9us
2023-07-31T16:07:59.644533 [DL-PHY6 ] [I] [   886.2] PDCCH: rnti=0x4606 ss_id=1 format=0_0 cce=0 al=4 t=34
...
Active RF plugins: libsrsran_rf_uhd.so libsrsran_rf_zmq.so
Inactive RF plugins: 
Reading configuration file /home/mobileuser/5g/srsran-config/soft-ue.conf...

Built in Debug mode using commit 5a4eb5d6c on branch master.

Opening 1 channels in RF device=uhd with args=default
Supported RF device list: UHD zmq file
[INFO] [UHD] linux; Clang version 14.0.0 ; Boost_107400; UHD_4.4.0.0-0-g5fac246b
[INFO] [LOGGING] Fastpath logging disabled at runtime.
Opening USRP channels=1, args: type=b200,master_clock_rate=23.04e6
[INFO] [UHD RF] RF UHD Generic instance constructed
[INFO] [B200] Detected Device: B210
[INFO] [B200] Operating over USB 3.
[INFO] [B200] Initialize CODEC control...
[INFO] [B200] Initialize Radio control...
[INFO] [B200] Performing register loopback test... 
[INFO] [B200] Register loopback test passed
[INFO] [B200] Performing register loopback test... 
[INFO] [B200] Register loopback test passed
[INFO] [B200] Asking for clock rate 23.040000 MHz... 
[INFO] [B200] Actually got clock rate 23.040000 MHz.
Setting manual TX/RX offset to 300 samples
Waiting PHY to initialize ... done!
Attaching UE...
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8014
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8174
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8334
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8494
RF status: O=1, U=0, L=0
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8654
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8814
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=8974

...

RF status: O=0, U=1, L=4
RF status: O=0, U=1, L=1
RF status: O=0, U=1, L=2
RF status: O=0, U=1, L=2
RF status: O=0, U=2, L=6
RF status: O=0, U=2, L=10
RF status: O=0, U=2, L=13
RF status: O=0, U=1, L=4
RF status: O=0, U=1, L=2
RF status: O=0, U=1, L=2
RF status: O=0, U=1, L=6
RF status: O=0, U=1, L=5
RF status: O=0, U=1, L=3
RF status: O=0, U=3, L=14
RF status: O=0, U=1, L=3
RF status: O=0, U=1, L=4
RF status: O=0, U=2, L=9
RF status: O=0, U=2, L=2
[INFO] [UHD RF] Tx while waiting for EOB, timed out... 447.58 >= 447.58. Starting new burst...
RF status: O=0, U=1, L=3
RF status: O=0, U=1, L=8
RF status: O=0, U=2, L=10
RF status: O=0, U=2, L=11
RF status: O=0, U=2, L=10
RF status: O=0, U=1, L=6
RF status: O=0, U=1, L=5
RF status: O=0, U=2, L=7
RF status: O=0, U=1, L=0
RF status: O=0, U=1, L=0

tail -f ue.log

...
2023-07-31T16:08:21.549849 [PHY-SA ] [D] [   29] SYNC:  state=CAMPING, tti=29
2023-07-31T16:08:21.549849 [MAC    ] [D] [   38] Running MAC tti=38
2023-07-31T16:08:21.549852 [MAC    ] [D] [   38] Update Bj: lcid=0, Bj=0
2023-07-31T16:08:21.549853 [MAC    ] [D] [   38] Update Bj: lcid=1, Bj=0
2023-07-31T16:08:21.549857 [MAC    ] [D] [   38] RA:    IDLE:    rar_window_start=-1, rar_window_length=-1
2023-07-31T16:08:21.549858 [MAC-NR ] [D] [   38] Running MAC tti=38
2023-07-31T16:08:21.549866 [MAC-NR ] [D] [   38] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [lcg0=0, ] [lcid0=0, ]
2023-07-31T16:08:21.549872 [STCK   ] [D] tti_tprof: duration=0 msec
2023-07-31T16:08:21.550879 [PHY-SA ] [D] [   29] run_stack_tti: from recv
2023-07-31T16:08:21.550881 [PHY-SA ] [D] [   29] run_stack_tti: calling stack tti=39, tti_jump=1
2023-07-31T16:08:21.550882 [PHY-SA ] [D] [   29] run_stack_tti: stack called
2023-07-31T16:08:21.550883 [PHY-SA ] [D] [   29] SYNC:  received 11520 samples from radio
2023-07-31T16:08:21.550932 [MAC    ] [D] [   39] Running MAC tti=39
2023-07-31T16:08:21.550934 [MAC    ] [D] [   39] Update Bj: lcid=0, Bj=0
2023-07-31T16:08:21.550934 [MAC    ] [D] [   39] Update Bj: lcid=1, Bj=0
2023-07-31T16:08:21.550940 [MAC    ] [D] [   39] RA:    IDLE:    rar_window_start=-1, rar_window_length=-1
2023-07-31T16:08:21.550941 [MAC-NR ] [D] [   39] Running MAC tti=39
2023-07-31T16:08:21.550950 [MAC-NR ] [D] [   39] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [lcg0=0, ] [lcid0=0, ]
2023-07-31T16:08:21.550953 [PHY-SA ] [D] [   30] SYNC:  state=CAMPING, tti=30
2023-07-31T16:08:21.550956 [STCK   ] [D] tti_tprof: duration=0 msec
2023-07-31T16:08:21.551895 [PHY-SA ] [D] [   30] run_stack_tti: from recv
2023-07-31T16:08:21.551897 [PHY-SA ] [D] [   30] run_stack_tti: calling stack tti=40, tti_jump=1
2023-07-31T16:08:21.551898 [PHY-SA ] [D] [   30] run_stack_tti: stack called
2023-07-31T16:08:21.551898 [PHY-SA ] [D] [   30] SYNC:  received 11520 samples from radio
2023-07-31T16:08:21.551905 [MAC    ] [D] [   40] Running MAC tti=40
2023-07-31T16:08:21.551906 [MAC    ] [D] [   40] Update Bj: lcid=0, Bj=0
2023-07-31T16:08:21.551907 [MAC    ] [D] [   40] Update Bj: lcid=1, Bj=0
2023-07-31T16:08:21.551912 [MAC    ] [D] [   40] RA:    IDLE:    rar_window_start=-1, rar_window_length=-1
...

Expected Behavior

srsue connects

Actual Behaviour

srsue does not connect

Steps to reproduce the problem

grep -v "^\s*#" ue.conf| grep -v "^\s*$"
[rf]
freq_offset = 0
tx_gain = 50
rx_gain = 40
srate = 11.52e6
nof_antennas = 1
device_name = uhd
time_adv_nsamples = 300
[rat.eutra]
dl_earfcn = 2850
nof_carriers = 0
[rat.nr]
bands = 3
nof_carriers = 1
[pcap]
enable = none
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 = none
all_hex_limit = 32
filename = /tmp/ue.log
file_max_size = -1
[usim]
mode = pcsc
imsi = ....
imei = 353490069873319
[rrc]
ue_category       = 4
release           = 15
[nas]
apn = internet
apn_protocol = ipv4
[gw]
[gui]
enable = false
[channel.dl]
[channel.dl.awgn]
[channel.dl.fading]
[channel.dl.delay]
[channel.dl.rlf]
[channel.dl.hst]
[channel.ul]
[channel.ul.awgn]
[channel.ul.fading]
[channel.ul.delay]
[channel.ul.rlf]
[channel.ul.hst]
[phy]
[phy.nr]
[cfr]
[sim]
[general]

grep -v "^\s*#" gnb.conf | grep -v "^\s*$"
amf:
  addr: 127.0.0.5                 # The address or hostname of the AMF.
  bind_addr: 127.0.0.1              # A local IP that the gNB binds to for traffic from the AMF.
ru_sdr:
  device_driver: uhd                                            # The RF driver name.
  device_args: type=b200,num_recv_frames=64,num_send_frames=64  # Optionally pass arguments to the selected RF driver.
  srate: 11.52                                                  # RF sample rate might need to be adjusted according to selected bandwidth.
  otw_format: sc12
  tx_gain: 70                                                   # Transmit gain of the RF might need to adjusted to the given situation.
  rx_gain: 60                                                   # Receive gain of the RF might need to adjusted to the given situation.
cell_cfg:
  dl_arfcn: 368500                  # ARFCN of the downlink carrier (center frequency).
  band: 3                          # The NR band.
  channel_bandwidth_MHz: 10         # Bandwith in MHz. Number of PRBs will be automatically derived.
  common_scs: 15                    # Subcarrier spacing in kHz used for data.
  plmn: "00101"                     # PLMN broadcasted by the gNB.
  tac: 1                            # Tracking area code (needs to match the core configuration).
  pdcch:
    dedicated:
        ss2_type: common
        dci_format_0_1_and_1_1: false
log:
  filename: /tmp/gnb.log            # Path of the log file.
  all_level: info                # Logging level applied to all layers.
pcap:
  mac_enable: true                 # Set to true to enable MAC-layer PCAPs.
  mac_filename: /tmp/gnb_mac.pcap   # Path where the MAC PCAP is stored.
  ngap_enable: true                # Set to true to enable NGAP PCAPs.
  ngap_filename: /tmp/gnb_ngap.pcap # Path where the NGAP PCAP is stored.
brendan-mcauliffe commented 1 year ago

Hi @eulenleber ,

You are getting a lot of lates and underflows on the UE machine. I would first try to get rid of these, as they may be the cause of the UE not being able to connect. You can try running the following command to set your CPU governor to performance:

echo "performance" | sudo tee /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor

You can also reduce the log level being reported, as this can take up compute power that the UE may need. Try setting your logs to info for the UE - it is currently set to debug.

If the issue persists after trying the above, please attach the logs and pcaps for the test. You should leave the logs in info mode for this.

eulenleber commented 1 year ago

Thank you very much, I'll have to check whether I have the access to more powerful hardware. Since that's a reoccurring phenomenon I suggest a kind of explicit warning message like "too many L's or U's consider upgrading the hardware"

Also a specific minimal hardware requirement would help (at least in the https://docs.srsran.com/projects/project/en/latest/tutorials/source/srsUE/source/index.html there's just an Ubuntu :v: PC :v: mentioned)

I will come back to this.

ncmatson commented 1 year ago

Any update on this issue? We're seeing largely the same behavior. We have even tried using different b210s and different host machines but the underflow messages still remain. What's also confusing is that even though the UE never connects, the behavior varies in a seemingly random way. Sometimes the UE output prints information about the Random Access transmission, and sometimes it doesn't. Sometimes the UE log file has "SYNC" issues, sometimes it has "SFN does not match" issues (like in the attached log)

Our setup looks like the following ue host -> usrp b210 -> 30 dB attenuation -> usrp b210 -> gnb/open5gs core host.

We're using UHD 3.15 and commit 1afd7240f2b5e2061ab4158e8fcdacb15961813a for srsRAN_Project and fa56836b14dc6ad7ce0c3484a1944ebe2cdbe63b for srsRAN_4G for the UE.

gnb.log

ue.log ue_rf.txt gnb_rf_b210_fdd_srsUE.txt

ismagom commented 10 months ago

Hi @ncmatson , it seems your issue is different. I don't see Lates/Underflows in your logs. Your issue is CFO: 

2023-09-05T15:52:00.598835 [RRC-NR ] [I] Proc "Cell Selection" - Cell search found ARFCN=0 PCI=1 epre=-36.4 snr=+22.8 cfo=-3951.8 delay=+0.0  sfn=957 ssb_idx=0 hrf=n scs=15 ssb_offset=6

Please use an external clock as described in the tutorial.