search

srsran / srsRAN_4G

Open source SDR 4G software suite from Software Radio Systems (SRS) https://docs.srsran.com/projects/4g
https://www.srsran.com
GNU Affero General Public License v3.0
3.38k stars 1.11k forks source link

srsUE doesn't attach #735

Closed matan1008 closed 2 years ago

matan1008 commented 2 years ago

Issue Description

I am trying to connect a cell I scanned with cell_serach and for some cell it works and for some cell it doesn't. When looking in the ue.log, I found that even when it did decode the MIB successfully, it also fails.

Setup Details

Expected Behavior

Either to find the cell and try to connect to it or not find the cell.

Actual Behaviour

The srsUE searches for a cell and fails to connect. Usually the output looks like:

Opening 1 channels in RF device=default with args=clock=gpsdo
[INFO] [UHD] linux; GNU C++ version 9.2.1 20200304; Boost_107100; UHD_3.15.0.0-2build5
[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] Detecting internal GPSDO.... 
[INFO] [GPS] Found an internal GPSDO: GPSTCXO , Firmware Rev 0.929a
[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 USRP time to 1136824006.000000s
[INFO] [MULTI_USRP]     1) catch time transition at pps edge
[INFO] [MULTI_USRP]     2) set times next pps (synchronously)
Warning: Failed to create thread with real-time priority. Creating it with normal priority: No such file or directory
Waiting PHY to initialize ... Warning: Failed to create thread with real-time priority. Creating it with normal priority: Success
Warning: Failed to create thread with real-time priority. Creating it with normal priority: Success
Warning: Failed to create thread with real-time priority. Creating it with normal priority: Success
Warning: Failed to create thread with real-time priority. Creating it with normal priority: Success
done!
Attaching UE...
.
.
.
..
...
..
..
.
.....
.
......

But from time to time it prints:

.
.
.
Found Cell:  Mode=FDD, PCI=2, PRB=6, Ports=2, CFO=-4.7 KHz
.
.....
.

Steps to reproduce the problem

I ran the srsUE with --rat.eutra.dl_earfcn 1282 --phy.force_N_id_2 2 THe config files are as in the examples (except using device_args = clock=gpsdo) , I tried to play with the phy category:

in_sync_rsrp_dbm_th    = -200.0
in_sync_snr_db_th      = -200.0
nof_in_sync_events     = 1
nof_out_of_sync_events = 400000

But it didn't make it better.

Additional Information

Debug log from when it parses the MIB:

05:20:13.670414 [NAS    ] [D] Attempting to select PLMN
05:20:13.670416 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.670486 [PHY_LIB] [D] [ 1422]  Trying 1 TX antennas with 4 frames
05:20:13.672495 [PHY_LIB] [D] [ 1422]  Trying 2 TX antennas with 4 frames
05:20:13.673098 [PHY_LIB] [I] [ 1422]  Decoded PBCH: src=3, dst=1, nb=1, sfn_offset=1
05:20:13.673109 [PHY_LIB] [I] [ 1422]  srsran_pbch_decode return: 1
05:20:13.673116 [PHY_LIB] [I] [ 1422]  MIB decoded: 8, snr=-0.4 dB
05:20:13.673163 [PHY    ] [I] [    0] SYNC:  MIB Decoded: Mode=FDD, PCI=2, PRB=6, Ports=2, CFO=-4.7 KHz
05:20:13.673206 [PHY    ] [D] [    0] SYNC:  state=SEARCH, tti=1423
05:20:13.673214 [PHY    ] [D] [    0] Discarding 11520 samples
05:20:13.673229 [RLC    ] [I] BCCH BCH message received.
    0000: 1b 1a 29
05:20:13.673262 [PHY    ] [I] [    0] Cell Search: Found cell with PCI=2 with 6 PRB
05:20:13.673279 [RRC    ] [D] BCCH-BCH - Rx MIB (3 B)
    0000: 1b 1a 29
05:20:13.673280 [PHY    ] [I] [    0] Cell Search: No more frequencies in the current EARFCN set
05:20:13.673284 [RRC    ] [D] Content:
[
  {
    "BCCH-BCH-Message": {
      "message": {
        "dl-Bandwidth": "n6",
        "phich-Config": {
          "phich-Duration": "extended",
          "phich-Resource": "one"
        },
        "systemFrameNumber": "11000110",
        "schedulingInfoSIB1-BR-r13": 17,
        "systemInfoUnchanged-BR-r15": false,
        "spare": "1001"
      }
    }
  }
]
05:20:13.673298 [RRC    ] [I] FSM "phy_controller" - PHY cell search completed. Found cell {pci=2, dl_earfcn=1282}
05:20:13.673303 [RRC    ] [I] FSM "phy_controller" - transition detected - searching_cell -> unknown_st (cause: cell_srch_res)
05:20:13.673306 [RRC    ] [I] Proc "Cell Search" - Cell found in this frequency. Setting new serving cell EARFCN=1282 PCI=2 ...
05:20:13.673324 [RRC    ] [I] Added neighbour cell {cell_id: 0x0, pci: 2, dl_earfcn: 1282, rsrp=+nan, cfo=-5740.2} is serving cell
05:20:13.673333 [RRC    ] [D] Neighbours: Empty
05:20:13.673338 [RRC    ] [I] FSM "phy_controller" - transition detected - unknown_st -> selecting_cell (cause: cell_sel_cmd)
05:20:13.673339 [RRC    ] [I] FSM "selecting_cell" - Starting for pci=2, earfcn=1282
05:20:13.673342 [PHY    ] [I] [    0] Cell Select: Going to IDLE
05:20:13.673352 [PHY    ] [I] [    0] Resetting PHY...
05:20:13.673354 [PHY    ] [I] [    0] PHY:   Set TA base: n_ta: 0, ta_usec: 0.0
05:20:13.673932 [PHY_LIB] [D] [ 1423]  SYNC init with frame_size=1920, max_offset=1920 and fft_size=128
05:20:13.674354 [PHY_LIB] [D] [ 1423]  SYNC init with frame_size=1920, max_offset=32 and fft_size=128
05:20:13.674371 [PHY_LIB] [D] [ 1423]  Generated SSS for N_id_1=0, cell_id=2
05:20:13.674511 [PHY_LIB] [D] [ 1423]  Init FFT symbol_sz=128, nof_symbols=7, cp=Normal, nof_re=72, nof_guards=28
05:20:13.674561 [PHY    ] [I] [    0] Cell Select: Setting CAMPING sampling rate
05:20:13.674564 [PHY    ] [I] [    0] SYNC:  Setting sampling rate 1.92 MHz
05:20:13.676677 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.676692 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1423, tti_jump=1
05:20:13.676707 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.676712 [PHY    ] [D] [    0] SYNC:  received 11520 samples from radio
05:20:13.676718 [PHY    ] [D] [    0] SYNC:  state=IDLE, tti=1424
05:20:13.676721 [PHY    ] [D] [    0] Discarding 1920 samples
05:20:13.676788 [MAC    ] [D] [ 1423] Running MAC tti=1423
05:20:13.676792 [MAC    ] [D] [ 1423] Update Bj: lcid=0, Bj=0
05:20:13.676793 [MAC    ] [D] [ 1423] Update Bj: lcid=1, Bj=0
05:20:13.676803 [MAC    ] [D] [ 1423] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.676805 [MAC-NR ] [D] [ 1423] Running MAC tti=1423
05:20:13.676814 [MAC-NR ] [D] [ 1423] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.676825 [NAS    ] [D] Attempting to select PLMN
05:20:13.676828 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.677705 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.677721 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1424, tti_jump=6
05:20:13.677736 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.677742 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.677747 [PHY    ] [D] [    0] SYNC:  state=IDLE, tti=1425
05:20:13.677751 [PHY    ] [D] [    0] Discarding 1920 samples
05:20:13.677765 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.677770 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1425, tti_jump=1
05:20:13.677777 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.677779 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.677781 [PHY    ] [D] [    0] SYNC:  state=IDLE, tti=1426
05:20:13.677815 [MAC    ] [D] [ 1419] Running MAC tti=1419
05:20:13.677818 [MAC    ] [D] [ 1419] Update Bj: lcid=0, Bj=0
05:20:13.677820 [MAC    ] [D] [ 1419] Update Bj: lcid=1, Bj=0
05:20:13.677835 [MAC    ] [D] [ 1419] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677838 [MAC-NR ] [D] [ 1419] Running MAC tti=1419
05:20:13.677847 [MAC-NR ] [D] [ 1419] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677853 [MAC    ] [D] [ 1420] Running MAC tti=1420
05:20:13.677854 [MAC    ] [D] [ 1420] Update Bj: lcid=0, Bj=0
05:20:13.677855 [MAC    ] [D] [ 1420] Update Bj: lcid=1, Bj=0
05:20:13.677856 [MAC    ] [D] [ 1420] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677858 [MAC-NR ] [D] [ 1420] Running MAC tti=1420
05:20:13.677863 [MAC-NR ] [D] [ 1420] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677864 [MAC    ] [D] [ 1421] Running MAC tti=1421
05:20:13.677871 [MAC    ] [D] [ 1421] Update Bj: lcid=0, Bj=0
05:20:13.677875 [MAC    ] [D] [ 1421] Update Bj: lcid=1, Bj=0
05:20:13.677878 [MAC    ] [D] [ 1421] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677879 [MAC-NR ] [D] [ 1421] Running MAC tti=1421
05:20:13.677881 [MAC-NR ] [D] [ 1421] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677882 [MAC    ] [D] [ 1422] Running MAC tti=1422
05:20:13.677884 [MAC    ] [D] [ 1422] Update Bj: lcid=0, Bj=0
05:20:13.677884 [MAC    ] [D] [ 1422] Update Bj: lcid=1, Bj=0
05:20:13.677886 [MAC    ] [D] [ 1422] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677887 [MAC-NR ] [D] [ 1422] Running MAC tti=1422
05:20:13.677889 [MAC-NR ] [D] [ 1422] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677891 [MAC    ] [D] [ 1423] Running MAC tti=1423
05:20:13.677892 [MAC    ] [D] [ 1423] Update Bj: lcid=0, Bj=0
05:20:13.677893 [MAC    ] [D] [ 1423] Update Bj: lcid=1, Bj=0
05:20:13.677894 [MAC    ] [D] [ 1423] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677895 [MAC-NR ] [D] [ 1423] Running MAC tti=1423
05:20:13.677903 [MAC-NR ] [D] [ 1423] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677904 [MAC    ] [D] [ 1424] Running MAC tti=1424
05:20:13.677911 [MAC    ] [D] [ 1424] Update Bj: lcid=0, Bj=0
05:20:13.677912 [MAC    ] [D] [ 1424] Update Bj: lcid=1, Bj=0
05:20:13.677913 [MAC    ] [D] [ 1424] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677914 [MAC-NR ] [D] [ 1424] Running MAC tti=1424
05:20:13.677916 [MAC-NR ] [D] [ 1424] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677922 [NAS    ] [D] Attempting to select PLMN
05:20:13.677926 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.677935 [MAC    ] [D] [ 1425] Running MAC tti=1425
05:20:13.677936 [MAC    ] [D] [ 1425] Update Bj: lcid=0, Bj=0
05:20:13.677937 [MAC    ] [D] [ 1425] Update Bj: lcid=1, Bj=0
05:20:13.677939 [MAC    ] [D] [ 1425] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.677943 [MAC-NR ] [D] [ 1425] Running MAC tti=1425
05:20:13.677945 [MAC-NR ] [D] [ 1425] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.677947 [NAS    ] [D] Attempting to select PLMN
05:20:13.677948 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.678669 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.678686 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1426, tti_jump=1
05:20:13.678699 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.678708 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.678772 [MAC    ] [D] [ 1426] Running MAC tti=1426
05:20:13.678787 [MAC    ] [D] [ 1426] Update Bj: lcid=0, Bj=0
05:20:13.678788 [MAC    ] [D] [ 1426] Update Bj: lcid=1, Bj=0
05:20:13.678795 [MAC    ] [D] [ 1426] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.678797 [MAC-NR ] [D] [ 1426] Running MAC tti=1426
05:20:13.678805 [MAC-NR ] [D] [ 1426] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.678813 [NAS    ] [D] Attempting to select PLMN
05:20:13.678816 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.678876 [PHY_LIB] [D] [ 1426]  PSS: id=2, peak_pos=936, peak_value=1.119477
05:20:13.678898 [PHY_LIB] [D] [ 1426]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=936 peak=1.12 threshold=3.00 CFO=-5.740 kHz
05:20:13.678908 [PHY_LIB] [I] [ 1426]  SYNC FIND: sf_idx=0, ret=0, peak_pos=936, peak_value=1.12, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.678911 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (0/100)
05:20:13.678915 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1427
05:20:13.679679 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.679696 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1427, tti_jump=1
05:20:13.679708 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.679711 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.679776 [MAC    ] [D] [ 1427] Running MAC tti=1427
05:20:13.679791 [MAC    ] [D] [ 1427] Update Bj: lcid=0, Bj=0
05:20:13.679792 [MAC    ] [D] [ 1427] Update Bj: lcid=1, Bj=0
05:20:13.679799 [MAC    ] [D] [ 1427] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.679801 [MAC-NR ] [D] [ 1427] Running MAC tti=1427
05:20:13.679808 [MAC-NR ] [D] [ 1427] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.679821 [NAS    ] [D] Attempting to select PLMN
05:20:13.679824 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.679849 [PHY_LIB] [D] [ 1427]  PSS: id=2, peak_pos=960, peak_value=2.519037
05:20:13.679861 [PHY_LIB] [D] [ 1427]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=2.52 threshold=3.00 CFO=-5.740 kHz
05:20:13.679878 [PHY_LIB] [I] [ 1427]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=2.52, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.679879 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (1/100)
05:20:13.679883 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1428
05:20:13.680781 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.680797 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1428, tti_jump=1
05:20:13.680809 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.680812 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.680873 [MAC    ] [D] [ 1428] Running MAC tti=1428
05:20:13.680888 [MAC    ] [D] [ 1428] Update Bj: lcid=0, Bj=0
05:20:13.680889 [MAC    ] [D] [ 1428] Update Bj: lcid=1, Bj=0
05:20:13.680896 [MAC    ] [D] [ 1428] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.680898 [MAC-NR ] [D] [ 1428] Running MAC tti=1428
05:20:13.680905 [MAC-NR ] [D] [ 1428] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.680913 [NAS    ] [D] Attempting to select PLMN
05:20:13.680915 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.680950 [PHY_LIB] [D] [ 1428]  PSS: id=2, peak_pos=1790, peak_value=1.062127
05:20:13.680960 [PHY_LIB] [D] [ 1428]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1790 peak=1.06 threshold=3.00 CFO=-5.740 kHz
05:20:13.680969 [PHY_LIB] [I] [ 1428]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1790, peak_value=1.06, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.680971 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (2/100)
05:20:13.680974 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1429
05:20:13.681845 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.681861 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1429, tti_jump=1
05:20:13.681873 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.681877 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.681938 [MAC    ] [D] [ 1429] Running MAC tti=1429
05:20:13.681953 [MAC    ] [D] [ 1429] Update Bj: lcid=0, Bj=0
05:20:13.681954 [MAC    ] [D] [ 1429] Update Bj: lcid=1, Bj=0
05:20:13.681961 [MAC    ] [D] [ 1429] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.681963 [MAC-NR ] [D] [ 1429] Running MAC tti=1429
05:20:13.681970 [MAC-NR ] [D] [ 1429] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.681978 [NAS    ] [D] Attempting to select PLMN
05:20:13.681981 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.682014 [PHY_LIB] [D] [ 1429]  PSS: id=2, peak_pos=966, peak_value=1.207337
05:20:13.682032 [PHY_LIB] [D] [ 1429]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=966 peak=1.21 threshold=3.00 CFO=-5.740 kHz
05:20:13.682041 [PHY_LIB] [I] [ 1429]  SYNC FIND: sf_idx=0, ret=0, peak_pos=966, peak_value=1.21, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.682048 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (3/100)
05:20:13.682052 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1430
05:20:13.682904 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.682920 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1430, tti_jump=1
05:20:13.682932 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.682936 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.682997 [MAC    ] [D] [ 1430] Running MAC tti=1430
05:20:13.683012 [MAC    ] [D] [ 1430] Update Bj: lcid=0, Bj=0
05:20:13.683013 [MAC    ] [D] [ 1430] Update Bj: lcid=1, Bj=0
05:20:13.683020 [MAC    ] [D] [ 1430] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.683022 [MAC-NR ] [D] [ 1430] Running MAC tti=1430
05:20:13.683029 [MAC-NR ] [D] [ 1430] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.683036 [NAS    ] [D] Attempting to select PLMN
05:20:13.683039 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.683071 [PHY_LIB] [D] [ 1430]  PSS: id=2, peak_pos=454, peak_value=1.270210
05:20:13.683086 [PHY_LIB] [D] [ 1430]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=454 peak=1.27 threshold=3.00 CFO=-5.740 kHz
05:20:13.683096 [PHY_LIB] [I] [ 1430]  SYNC FIND: sf_idx=0, ret=0, peak_pos=454, peak_value=1.27, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.683113 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (4/100)
05:20:13.683117 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1431
05:20:13.683944 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.683961 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1431, tti_jump=1
05:20:13.683973 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.683982 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.684046 [MAC    ] [D] [ 1431] Running MAC tti=1431
05:20:13.684061 [MAC    ] [D] [ 1431] Update Bj: lcid=0, Bj=0
05:20:13.684062 [MAC    ] [D] [ 1431] Update Bj: lcid=1, Bj=0
05:20:13.684069 [MAC    ] [D] [ 1431] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.684071 [MAC-NR ] [D] [ 1431] Running MAC tti=1431
05:20:13.684078 [MAC-NR ] [D] [ 1431] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.684085 [NAS    ] [D] Attempting to select PLMN
05:20:13.684088 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.684095 [STCK   ] [I] tti_tprof: {mean, max, min} = {0.02, 0, 0} msec
05:20:13.684121 [PHY_LIB] [D] [ 1431]  PSS: id=2, peak_pos=1370, peak_value=1.225794
05:20:13.684131 [PHY_LIB] [D] [ 1431]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1370 peak=1.23 threshold=3.00 CFO=-5.740 kHz
05:20:13.684141 [PHY_LIB] [I] [ 1431]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1370, peak_value=1.23, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.684143 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (5/100)
05:20:13.684146 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1432
05:20:13.685006 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.685023 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1432, tti_jump=1
05:20:13.685036 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.685046 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.685110 [MAC    ] [D] [ 1432] Running MAC tti=1432
05:20:13.685124 [MAC    ] [D] [ 1432] Update Bj: lcid=0, Bj=0
05:20:13.685126 [MAC    ] [D] [ 1432] Update Bj: lcid=1, Bj=0
05:20:13.685133 [MAC    ] [D] [ 1432] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.685135 [MAC-NR ] [D] [ 1432] Running MAC tti=1432
05:20:13.685142 [MAC-NR ] [D] [ 1432] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.685149 [NAS    ] [D] Attempting to select PLMN
05:20:13.685152 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.685181 [PHY_LIB] [D] [ 1432]  PSS: id=2, peak_pos=960, peak_value=2.844165
05:20:13.685191 [PHY_LIB] [D] [ 1432]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=2.84 threshold=3.00 CFO=-5.740 kHz
05:20:13.685201 [PHY_LIB] [I] [ 1432]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=2.84, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.685203 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (6/100)
05:20:13.685213 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1433
05:20:13.686061 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.686078 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1433, tti_jump=1
05:20:13.686091 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.686100 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.686164 [MAC    ] [D] [ 1433] Running MAC tti=1433
05:20:13.686179 [MAC    ] [D] [ 1433] Update Bj: lcid=0, Bj=0
05:20:13.686180 [MAC    ] [D] [ 1433] Update Bj: lcid=1, Bj=0
05:20:13.686187 [MAC    ] [D] [ 1433] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.686189 [MAC-NR ] [D] [ 1433] Running MAC tti=1433
05:20:13.686196 [MAC-NR ] [D] [ 1433] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.686204 [NAS    ] [D] Attempting to select PLMN
05:20:13.686207 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.686236 [PHY_LIB] [D] [ 1433]  PSS: id=2, peak_pos=1317, peak_value=1.351577
05:20:13.686247 [PHY_LIB] [D] [ 1433]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1317 peak=1.35 threshold=3.00 CFO=-5.740 kHz
05:20:13.686256 [PHY_LIB] [I] [ 1433]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1317, peak_value=1.35, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.686258 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (7/100)
05:20:13.686261 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1434
05:20:13.687120 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.687137 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1434, tti_jump=1
05:20:13.687150 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.687154 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.687221 [MAC    ] [D] [ 1434] Running MAC tti=1434
05:20:13.687236 [MAC    ] [D] [ 1434] Update Bj: lcid=0, Bj=0
05:20:13.687237 [MAC    ] [D] [ 1434] Update Bj: lcid=1, Bj=0
05:20:13.687244 [MAC    ] [D] [ 1434] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.687246 [MAC-NR ] [D] [ 1434] Running MAC tti=1434
05:20:13.687253 [MAC-NR ] [D] [ 1434] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.687260 [NAS    ] [D] Attempting to select PLMN
05:20:13.687263 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.687292 [PHY_LIB] [D] [ 1434]  PSS: id=2, peak_pos=1467, peak_value=1.135983
05:20:13.687303 [PHY_LIB] [D] [ 1434]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1467 peak=1.14 threshold=3.00 CFO=-5.740 kHz
05:20:13.687312 [PHY_LIB] [I] [ 1434]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1467, peak_value=1.14, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.687314 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (8/100)
05:20:13.687318 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1435
05:20:13.688187 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.688203 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1435, tti_jump=1
05:20:13.688216 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.688220 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.688292 [MAC    ] [D] [ 1435] Running MAC tti=1435
05:20:13.688306 [MAC    ] [D] [ 1435] Update Bj: lcid=0, Bj=0
05:20:13.688307 [MAC    ] [D] [ 1435] Update Bj: lcid=1, Bj=0
05:20:13.688314 [MAC    ] [D] [ 1435] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.688316 [MAC-NR ] [D] [ 1435] Running MAC tti=1435
05:20:13.688323 [MAC-NR ] [D] [ 1435] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.688334 [NAS    ] [D] Attempting to select PLMN
05:20:13.688337 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.688354 [PHY_LIB] [D] [ 1435]  PSS: id=2, peak_pos=422, peak_value=1.000852
05:20:13.688365 [PHY_LIB] [D] [ 1435]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=422 peak=1.00 threshold=3.00 CFO=-5.740 kHz
05:20:13.688374 [PHY_LIB] [I] [ 1435]  SYNC FIND: sf_idx=0, ret=0, peak_pos=422, peak_value=1.00, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.688376 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (9/100)
05:20:13.688380 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1436
05:20:13.689272 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.689287 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1436, tti_jump=1
05:20:13.689298 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.689301 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.689362 [MAC    ] [D] [ 1436] Running MAC tti=1436
05:20:13.689371 [MAC    ] [D] [ 1436] Update Bj: lcid=0, Bj=0
05:20:13.689372 [MAC    ] [D] [ 1436] Update Bj: lcid=1, Bj=0
05:20:13.689379 [MAC    ] [D] [ 1436] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.689381 [MAC-NR ] [D] [ 1436] Running MAC tti=1436
05:20:13.689388 [MAC-NR ] [D] [ 1436] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.689395 [NAS    ] [D] Attempting to select PLMN
05:20:13.689398 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.689424 [PHY_LIB] [D] [ 1436]  PSS: id=2, peak_pos=1841, peak_value=1.027302
05:20:13.689432 [PHY_LIB] [D] [ 1436]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1841 peak=1.03 threshold=3.00 CFO=-5.740 kHz
05:20:13.689439 [PHY_LIB] [I] [ 1436]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1841, peak_value=1.03, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.689441 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (10/100)
05:20:13.689444 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1437
05:20:13.690301 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.690315 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1437, tti_jump=1
05:20:13.690325 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.690327 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.690388 [MAC    ] [D] [ 1437] Running MAC tti=1437
05:20:13.690391 [MAC    ] [D] [ 1437] Update Bj: lcid=0, Bj=0
05:20:13.690392 [MAC    ] [D] [ 1437] Update Bj: lcid=1, Bj=0
05:20:13.690399 [MAC    ] [D] [ 1437] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.690401 [MAC-NR ] [D] [ 1437] Running MAC tti=1437
05:20:13.690408 [MAC-NR ] [D] [ 1437] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.690415 [NAS    ] [D] Attempting to select PLMN
05:20:13.690418 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.690438 [PHY_LIB] [D] [ 1437]  PSS: id=2, peak_pos=960, peak_value=1.615479
05:20:13.690446 [PHY_LIB] [D] [ 1437]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=1.62 threshold=3.00 CFO=-5.740 kHz
05:20:13.690453 [PHY_LIB] [I] [ 1437]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=1.62, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.690455 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (11/100)
05:20:13.690458 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1438
05:20:13.691406 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.691420 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1438, tti_jump=1
05:20:13.691430 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.691432 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.691497 [MAC    ] [D] [ 1438] Running MAC tti=1438
05:20:13.691501 [MAC    ] [D] [ 1438] Update Bj: lcid=0, Bj=0
05:20:13.691503 [MAC    ] [D] [ 1438] Update Bj: lcid=1, Bj=0
05:20:13.691509 [MAC    ] [D] [ 1438] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.691512 [MAC-NR ] [D] [ 1438] Running MAC tti=1438
05:20:13.691519 [MAC-NR ] [D] [ 1438] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.691530 [NAS    ] [D] Attempting to select PLMN
05:20:13.691534 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.691563 [PHY_LIB] [D] [ 1438]  PSS: id=2, peak_pos=1041, peak_value=1.048369
05:20:13.691576 [PHY_LIB] [D] [ 1438]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1041 peak=1.05 threshold=3.00 CFO=-5.740 kHz
05:20:13.691583 [PHY_LIB] [I] [ 1438]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1041, peak_value=1.05, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.691585 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (12/100)
05:20:13.691588 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1439
05:20:13.692441 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.692455 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1439, tti_jump=1
05:20:13.692465 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.692467 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.692538 [MAC    ] [D] [ 1439] Running MAC tti=1439
05:20:13.692551 [MAC    ] [D] [ 1439] Update Bj: lcid=0, Bj=0
05:20:13.692553 [MAC    ] [D] [ 1439] Update Bj: lcid=1, Bj=0
05:20:13.692560 [MAC    ] [D] [ 1439] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.692562 [MAC-NR ] [D] [ 1439] Running MAC tti=1439
05:20:13.692569 [MAC-NR ] [D] [ 1439] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.692576 [NAS    ] [D] Attempting to select PLMN
05:20:13.692577 [PHY_LIB] [D] [ 1439]  PSS: id=2, peak_pos=1452, peak_value=1.098596
05:20:13.692579 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.692585 [PHY_LIB] [D] [ 1439]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1452 peak=1.10 threshold=3.00 CFO=-5.740 kHz
05:20:13.692592 [PHY_LIB] [I] [ 1439]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1452, peak_value=1.10, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.692594 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (13/100)
05:20:13.692601 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1440
05:20:13.693545 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.693560 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1440, tti_jump=1
05:20:13.693569 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.693571 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.693638 [MAC    ] [D] [ 1440] Running MAC tti=1440
05:20:13.693641 [MAC    ] [D] [ 1440] Update Bj: lcid=0, Bj=0
05:20:13.693642 [MAC    ] [D] [ 1440] Update Bj: lcid=1, Bj=0
05:20:13.693649 [MAC    ] [D] [ 1440] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.693651 [MAC-NR ] [D] [ 1440] Running MAC tti=1440
05:20:13.693658 [MAC-NR ] [D] [ 1440] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.693666 [NAS    ] [D] Attempting to select PLMN
05:20:13.693668 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.693681 [PHY_LIB] [D] [ 1440]  PSS: id=2, peak_pos=321, peak_value=1.097030
05:20:13.693689 [PHY_LIB] [D] [ 1440]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=321 peak=1.10 threshold=3.00 CFO=-5.740 kHz
05:20:13.693696 [PHY_LIB] [I] [ 1440]  SYNC FIND: sf_idx=0, ret=0, peak_pos=321, peak_value=1.10, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.693697 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (14/100)
05:20:13.693701 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1441
05:20:13.694603 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.694618 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1441, tti_jump=1
05:20:13.694628 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.694630 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.694690 [MAC    ] [D] [ 1441] Running MAC tti=1441
05:20:13.694704 [MAC    ] [D] [ 1441] Update Bj: lcid=0, Bj=0
05:20:13.694706 [MAC    ] [D] [ 1441] Update Bj: lcid=1, Bj=0
05:20:13.694713 [MAC    ] [D] [ 1441] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.694716 [MAC-NR ] [D] [ 1441] Running MAC tti=1441
05:20:13.694730 [MAC-NR ] [D] [ 1441] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.694738 [NAS    ] [D] Attempting to select PLMN
05:20:13.694741 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.694757 [PHY_LIB] [D] [ 1441]  PSS: id=2, peak_pos=156, peak_value=1.471300
05:20:13.694768 [PHY_LIB] [D] [ 1441]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=156 peak=1.47 threshold=3.00 CFO=-5.740 kHz
05:20:13.694775 [PHY_LIB] [I] [ 1441]  SYNC FIND: sf_idx=0, ret=0, peak_pos=156, peak_value=1.47, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.694777 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (15/100)
05:20:13.694781 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1442
05:20:13.694805 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.694808 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1442, tti_jump=1
05:20:13.694817 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.694820 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.694878 [MAC    ] [D] [ 1442] Running MAC tti=1442
05:20:13.694893 [MAC    ] [D] [ 1442] Update Bj: lcid=0, Bj=0
05:20:13.694895 [MAC    ] [D] [ 1442] Update Bj: lcid=1, Bj=0
05:20:13.694901 [MAC    ] [D] [ 1442] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.694903 [MAC-NR ] [D] [ 1442] Running MAC tti=1442
05:20:13.694911 [MAC-NR ] [D] [ 1442] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.694918 [NAS    ] [D] Attempting to select PLMN
05:20:13.694920 [PHY_LIB] [D] [ 1442]  PSS: id=2, peak_pos=960, peak_value=2.054737
05:20:13.694924 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.694925 [PHY_LIB] [D] [ 1442]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=2.05 threshold=3.00 CFO=-5.740 kHz
05:20:13.694931 [PHY_LIB] [I] [ 1442]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=2.05, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.694932 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (16/100)
05:20:13.694935 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1443
05:20:13.695695 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.695709 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1443, tti_jump=1
05:20:13.695718 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.695721 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.695783 [MAC    ] [D] [ 1443] Running MAC tti=1443
05:20:13.695786 [MAC    ] [D] [ 1443] Update Bj: lcid=0, Bj=0
05:20:13.695787 [MAC    ] [D] [ 1443] Update Bj: lcid=1, Bj=0
05:20:13.695795 [MAC    ] [D] [ 1443] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.695797 [MAC-NR ] [D] [ 1443] Running MAC tti=1443
05:20:13.695805 [MAC-NR ] [D] [ 1443] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.695813 [NAS    ] [D] Attempting to select PLMN
05:20:13.695816 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.695839 [PHY_LIB] [D] [ 1443]  PSS: id=2, peak_pos=450, peak_value=1.134215
05:20:13.695847 [PHY_LIB] [D] [ 1443]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=450 peak=1.13 threshold=3.00 CFO=-5.740 kHz
05:20:13.695853 [PHY_LIB] [I] [ 1443]  SYNC FIND: sf_idx=0, ret=0, peak_pos=450, peak_value=1.13, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.695855 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (17/100)
05:20:13.695859 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1444
05:20:13.696709 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.696724 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1444, tti_jump=1
05:20:13.696734 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.696737 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.696793 [MAC    ] [D] [ 1444] Running MAC tti=1444
05:20:13.696808 [MAC    ] [D] [ 1444] Update Bj: lcid=0, Bj=0
05:20:13.696810 [MAC    ] [D] [ 1444] Update Bj: lcid=1, Bj=0
05:20:13.696817 [MAC    ] [D] [ 1444] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.696820 [MAC-NR ] [D] [ 1444] Running MAC tti=1444
05:20:13.696827 [MAC-NR ] [D] [ 1444] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.696835 [NAS    ] [D] Attempting to select PLMN
05:20:13.696838 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.696856 [PHY_LIB] [D] [ 1444]  PSS: id=2, peak_pos=1596, peak_value=1.208475
05:20:13.696864 [PHY_LIB] [D] [ 1444]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1596 peak=1.21 threshold=3.00 CFO=-5.740 kHz
05:20:13.696872 [PHY_LIB] [I] [ 1444]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1596, peak_value=1.21, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.696877 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (18/100)
05:20:13.696881 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1445
05:20:13.697793 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.697807 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1445, tti_jump=1
05:20:13.697817 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.697820 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.697850 [MAC    ] [D] [ 1445] Running MAC tti=1445
05:20:13.697854 [MAC    ] [D] [ 1445] Update Bj: lcid=0, Bj=0
05:20:13.697855 [MAC    ] [D] [ 1445] Update Bj: lcid=1, Bj=0
05:20:13.697864 [MAC    ] [D] [ 1445] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.697867 [MAC-NR ] [D] [ 1445] Running MAC tti=1445
05:20:13.697876 [MAC-NR ] [D] [ 1445] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.697885 [NAS    ] [D] Attempting to select PLMN
05:20:13.697889 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.697940 [PHY_LIB] [D] [ 1445]  PSS: id=2, peak_pos=792, peak_value=1.017072
05:20:13.697956 [PHY_LIB] [D] [ 1445]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=792 peak=1.02 threshold=3.00 CFO=-5.740 kHz
05:20:13.697964 [PHY_LIB] [I] [ 1445]  SYNC FIND: sf_idx=0, ret=0, peak_pos=792, peak_value=1.02, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.697965 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (19/100)
05:20:13.697969 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1446
05:20:13.698862 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.698876 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1446, tti_jump=1
05:20:13.698887 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.698889 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.698915 [MAC    ] [D] [ 1446] Running MAC tti=1446
05:20:13.698918 [MAC    ] [D] [ 1446] Update Bj: lcid=0, Bj=0
05:20:13.698919 [MAC    ] [D] [ 1446] Update Bj: lcid=1, Bj=0
05:20:13.698926 [MAC    ] [D] [ 1446] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.698935 [MAC-NR ] [D] [ 1446] Running MAC tti=1446
05:20:13.698942 [MAC-NR ] [D] [ 1446] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.698949 [NAS    ] [D] Attempting to select PLMN
05:20:13.698952 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.699009 [PHY_LIB] [D] [ 1446]  PSS: id=2, peak_pos=1297, peak_value=1.030769
05:20:13.699025 [PHY_LIB] [D] [ 1446]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1297 peak=1.03 threshold=3.00 CFO=-5.740 kHz
05:20:13.699032 [PHY_LIB] [I] [ 1446]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1297, peak_value=1.03, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.699034 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (20/100)
05:20:13.699037 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1447
05:20:13.699939 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.699954 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1447, tti_jump=1
05:20:13.699967 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.699970 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.700003 [MAC    ] [D] [ 1447] Running MAC tti=1447
05:20:13.700007 [MAC    ] [D] [ 1447] Update Bj: lcid=0, Bj=0
05:20:13.700009 [MAC    ] [D] [ 1447] Update Bj: lcid=1, Bj=0
05:20:13.700020 [MAC    ] [D] [ 1447] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.700023 [MAC-NR ] [D] [ 1447] Running MAC tti=1447
05:20:13.700032 [MAC-NR ] [D] [ 1447] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.700043 [NAS    ] [D] Attempting to select PLMN
05:20:13.700046 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.700124 [PHY_LIB] [D] [ 1447]  PSS: id=2, peak_pos=960, peak_value=1.337971
05:20:13.700143 [PHY_LIB] [D] [ 1447]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=1.34 threshold=3.00 CFO=-5.740 kHz
05:20:13.700152 [PHY_LIB] [I] [ 1447]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=1.34, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.700155 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (21/100)
05:20:13.700158 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1448
05:20:13.700996 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.701009 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1448, tti_jump=1
05:20:13.701020 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.701022 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.701050 [MAC    ] [D] [ 1448] Running MAC tti=1448
05:20:13.701055 [MAC    ] [D] [ 1448] Update Bj: lcid=0, Bj=0
05:20:13.701057 [MAC    ] [D] [ 1448] Update Bj: lcid=1, Bj=0
05:20:13.701066 [MAC    ] [D] [ 1448] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.701069 [MAC-NR ] [D] [ 1448] Running MAC tti=1448
05:20:13.701079 [MAC-NR ] [D] [ 1448] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.701089 [NAS    ] [D] Attempting to select PLMN
05:20:13.701092 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.701154 [PHY_LIB] [D] [ 1448]  PSS: id=2, peak_pos=376, peak_value=1.031667
05:20:13.701168 [PHY_LIB] [D] [ 1448]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=376 peak=1.03 threshold=3.00 CFO=-5.740 kHz
05:20:13.701175 [PHY_LIB] [I] [ 1448]  SYNC FIND: sf_idx=0, ret=0, peak_pos=376, peak_value=1.03, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.701177 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (22/100)
05:20:13.701181 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1449
05:20:13.702021 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.702034 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1449, tti_jump=1
05:20:13.702045 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.702047 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.702106 [MAC    ] [D] [ 1449] Running MAC tti=1449
05:20:13.702109 [MAC    ] [D] [ 1449] Update Bj: lcid=0, Bj=0
05:20:13.702111 [MAC    ] [D] [ 1449] Update Bj: lcid=1, Bj=0
05:20:13.702118 [MAC    ] [D] [ 1449] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.702121 [MAC-NR ] [D] [ 1449] Running MAC tti=1449
05:20:13.702129 [MAC-NR ] [D] [ 1449] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.702137 [NAS    ] [D] Attempting to select PLMN
05:20:13.702146 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.702169 [PHY_LIB] [D] [ 1449]  PSS: id=2, peak_pos=1767, peak_value=1.211635
05:20:13.702183 [PHY_LIB] [D] [ 1449]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1767 peak=1.21 threshold=3.00 CFO=-5.740 kHz
05:20:13.702190 [PHY_LIB] [I] [ 1449]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1767, peak_value=1.21, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.702195 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (23/100)
05:20:13.702206 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1450
05:20:13.703069 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.703083 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1450, tti_jump=1
05:20:13.703095 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.703098 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.703156 [MAC    ] [D] [ 1450] Running MAC tti=1450
05:20:13.703165 [MAC    ] [D] [ 1450] Update Bj: lcid=0, Bj=0
05:20:13.703166 [MAC    ] [D] [ 1450] Update Bj: lcid=1, Bj=0
05:20:13.703173 [MAC    ] [D] [ 1450] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.703175 [MAC-NR ] [D] [ 1450] Running MAC tti=1450
05:20:13.703182 [MAC-NR ] [D] [ 1450] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.703190 [NAS    ] [D] Attempting to select PLMN
05:20:13.703192 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.703232 [PHY_LIB] [D] [ 1450]  PSS: id=2, peak_pos=1213, peak_value=1.353528
05:20:13.703246 [PHY_LIB] [D] [ 1450]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1213 peak=1.35 threshold=3.00 CFO=-5.740 kHz
05:20:13.703259 [PHY_LIB] [I] [ 1450]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1213, peak_value=1.35, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.703260 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (24/100)
05:20:13.703263 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1451
05:20:13.704176 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.704190 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1451, tti_jump=1
05:20:13.704200 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.704202 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.704266 [MAC    ] [D] [ 1451] Running MAC tti=1451
05:20:13.704269 [MAC    ] [D] [ 1451] Update Bj: lcid=0, Bj=0
05:20:13.704270 [MAC    ] [D] [ 1451] Update Bj: lcid=1, Bj=0
05:20:13.704278 [MAC    ] [D] [ 1451] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.704280 [MAC-NR ] [D] [ 1451] Running MAC tti=1451
05:20:13.704287 [MAC-NR ] [D] [ 1451] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.704295 [NAS    ] [D] Attempting to select PLMN
05:20:13.704298 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.704313 [PHY_LIB] [D] [ 1451]  PSS: id=2, peak_pos=204, peak_value=1.311579
05:20:13.704321 [PHY_LIB] [D] [ 1451]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=204 peak=1.31 threshold=3.00 CFO=-5.740 kHz
05:20:13.704331 [PHY_LIB] [I] [ 1451]  SYNC FIND: sf_idx=0, ret=0, peak_pos=204, peak_value=1.31, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.704338 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (25/100)
05:20:13.704341 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1452
05:20:13.705165 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.705179 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1452, tti_jump=1
05:20:13.705191 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.705194 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.705256 [MAC    ] [D] [ 1452] Running MAC tti=1452
05:20:13.705259 [MAC    ] [D] [ 1452] Update Bj: lcid=0, Bj=0
05:20:13.705260 [MAC    ] [D] [ 1452] Update Bj: lcid=1, Bj=0
05:20:13.705268 [MAC    ] [D] [ 1452] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.705270 [MAC-NR ] [D] [ 1452] Running MAC tti=1452
05:20:13.705278 [MAC-NR ] [D] [ 1452] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.705292 [NAS    ] [D] Attempting to select PLMN
05:20:13.705295 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.705302 [PHY_LIB] [D] [ 1452]  PSS: id=2, peak_pos=960, peak_value=2.002482
05:20:13.705310 [PHY_LIB] [D] [ 1452]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=2.00 threshold=3.00 CFO=-5.740 kHz
05:20:13.705317 [PHY_LIB] [I] [ 1452]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=2.00, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.705325 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (26/100)
05:20:13.705328 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1453
05:20:13.706251 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.706264 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1453, tti_jump=1
05:20:13.706274 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.706277 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.706339 [MAC    ] [D] [ 1453] Running MAC tti=1453
05:20:13.706342 [MAC    ] [D] [ 1453] Update Bj: lcid=0, Bj=0
05:20:13.706343 [MAC    ] [D] [ 1453] Update Bj: lcid=1, Bj=0
05:20:13.706351 [MAC    ] [D] [ 1453] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.706353 [MAC-NR ] [D] [ 1453] Running MAC tti=1453
05:20:13.706360 [MAC-NR ] [D] [ 1453] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.706368 [NAS    ] [D] Attempting to select PLMN
05:20:13.706371 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.706387 [PHY_LIB] [D] [ 1453]  PSS: id=2, peak_pos=1121, peak_value=1.035770
05:20:13.706395 [PHY_LIB] [D] [ 1453]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1121 peak=1.04 threshold=3.00 CFO=-5.740 kHz
05:20:13.706406 [PHY_LIB] [I] [ 1453]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1121, peak_value=1.04, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.706413 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (27/100)
05:20:13.706416 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1454
05:20:13.707343 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.707357 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1454, tti_jump=1
05:20:13.707366 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.707368 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.707430 [MAC    ] [D] [ 1454] Running MAC tti=1454
05:20:13.707433 [MAC    ] [D] [ 1454] Update Bj: lcid=0, Bj=0
05:20:13.707434 [MAC    ] [D] [ 1454] Update Bj: lcid=1, Bj=0
05:20:13.707442 [MAC    ] [D] [ 1454] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.707444 [MAC-NR ] [D] [ 1454] Running MAC tti=1454
05:20:13.707451 [MAC-NR ] [D] [ 1454] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.707459 [NAS    ] [D] Attempting to select PLMN
05:20:13.707486 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.707503 [PHY_LIB] [D] [ 1454]  PSS: id=2, peak_pos=1546, peak_value=1.088261
05:20:13.707514 [PHY_LIB] [D] [ 1454]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1546 peak=1.09 threshold=3.00 CFO=-5.740 kHz
05:20:13.707523 [PHY_LIB] [I] [ 1454]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1546, peak_value=1.09, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.707525 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (28/100)
05:20:13.707529 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1455
05:20:13.708400 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.708414 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1455, tti_jump=1
05:20:13.708423 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.708426 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.708454 [MAC    ] [D] [ 1455] Running MAC tti=1455
05:20:13.708459 [MAC    ] [D] [ 1455] Update Bj: lcid=0, Bj=0
05:20:13.708460 [MAC    ] [D] [ 1455] Update Bj: lcid=1, Bj=0
05:20:13.708469 [MAC    ] [D] [ 1455] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.708471 [MAC-NR ] [D] [ 1455] Running MAC tti=1455
05:20:13.708480 [MAC-NR ] [D] [ 1455] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.708489 [NAS    ] [D] Attempting to select PLMN
05:20:13.708492 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.708536 [PHY_LIB] [D] [ 1455]  PSS: id=2, peak_pos=1886, peak_value=1.389540
05:20:13.708544 [PHY_LIB] [D] [ 1455]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=1886 peak=1.39 threshold=3.00 CFO=-5.740 kHz
05:20:13.708551 [PHY_LIB] [I] [ 1455]  SYNC FIND: sf_idx=0, ret=0, peak_pos=1886, peak_value=1.39, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.708553 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (29/100)
05:20:13.708556 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1456
05:20:13.709436 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.709449 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1456, tti_jump=1
05:20:13.709458 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.709461 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.709520 [MAC    ] [D] [ 1456] Running MAC tti=1456
05:20:13.709523 [MAC    ] [D] [ 1456] Update Bj: lcid=0, Bj=0
05:20:13.709528 [MAC    ] [D] [ 1456] Update Bj: lcid=1, Bj=0
05:20:13.709536 [MAC    ] [D] [ 1456] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.709538 [MAC-NR ] [D] [ 1456] Running MAC tti=1456
05:20:13.709552 [MAC-NR ] [D] [ 1456] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.709564 [NAS    ] [D] Attempting to select PLMN
05:20:13.709572 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.709577 [PHY_LIB] [D] [ 1456]  PSS: id=2, peak_pos=314, peak_value=1.173298
05:20:13.709585 [PHY_LIB] [D] [ 1456]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=314 peak=1.17 threshold=3.00 CFO=-5.740 kHz
05:20:13.709592 [PHY_LIB] [I] [ 1456]  SYNC FIND: sf_idx=0, ret=0, peak_pos=314, peak_value=1.17, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.709594 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (30/100)
05:20:13.709598 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1457
05:20:13.710529 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.710543 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1457, tti_jump=1
05:20:13.710552 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.710554 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.710615 [MAC    ] [D] [ 1457] Running MAC tti=1457
05:20:13.710618 [MAC    ] [D] [ 1457] Update Bj: lcid=0, Bj=0
05:20:13.710619 [MAC    ] [D] [ 1457] Update Bj: lcid=1, Bj=0
05:20:13.710626 [MAC    ] [D] [ 1457] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.710629 [MAC-NR ] [D] [ 1457] Running MAC tti=1457
05:20:13.710636 [MAC-NR ] [D] [ 1457] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.710644 [NAS    ] [D] Attempting to select PLMN
05:20:13.710647 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.710664 [PHY_LIB] [D] [ 1457]  PSS: id=2, peak_pos=960, peak_value=1.690683
05:20:13.710678 [PHY_LIB] [D] [ 1457]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=960 peak=1.69 threshold=3.00 CFO=-5.740 kHz
05:20:13.710685 [PHY_LIB] [I] [ 1457]  SYNC FIND: sf_idx=0, ret=0, peak_pos=960, peak_value=1.69, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.710687 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (31/100)
05:20:13.710690 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1458
05:20:13.711574 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.711587 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1458, tti_jump=1
05:20:13.711596 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.711599 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.711626 [MAC    ] [D] [ 1458] Running MAC tti=1458
05:20:13.711630 [MAC    ] [D] [ 1458] Update Bj: lcid=0, Bj=0
05:20:13.711632 [MAC    ] [D] [ 1458] Update Bj: lcid=1, Bj=0
05:20:13.711640 [MAC    ] [D] [ 1458] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.711643 [MAC-NR ] [D] [ 1458] Running MAC tti=1458
05:20:13.711651 [MAC-NR ] [D] [ 1458] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.711660 [NAS    ] [D] Attempting to select PLMN
05:20:13.711663 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.711706 [PHY_LIB] [D] [ 1458]  PSS: id=2, peak_pos=479, peak_value=1.267491
05:20:13.711714 [PHY_LIB] [D] [ 1458]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=479 peak=1.27 threshold=3.00 CFO=-5.740 kHz
05:20:13.711721 [PHY_LIB] [I] [ 1458]  SYNC FIND: sf_idx=0, ret=0, peak_pos=479, peak_value=1.27, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.711723 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (32/100)
05:20:13.711726 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1459
05:20:13.711743 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.711744 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1459, tti_jump=1
05:20:13.711751 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.711752 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.711820 [MAC    ] [D] [ 1459] Running MAC tti=1459
05:20:13.711837 [MAC    ] [D] [ 1459] Update Bj: lcid=0, Bj=0
05:20:13.711839 [MAC    ] [D] [ 1459] Update Bj: lcid=1, Bj=0
05:20:13.711840 [PHY_LIB] [D] [ 1459]  PSS: id=2, peak_pos=947, peak_value=1.111668
05:20:13.711845 [PHY_LIB] [D] [ 1459]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=947 peak=1.11 threshold=3.00 CFO=-5.740 kHz
05:20:13.711847 [MAC    ] [D] [ 1459] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.711850 [MAC-NR ] [D] [ 1459] Running MAC tti=1459
05:20:13.711850 [PHY_LIB] [I] [ 1459]  SYNC FIND: sf_idx=0, ret=0, peak_pos=947, peak_value=1.11, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.711855 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (33/100)
05:20:13.711856 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1460
05:20:13.711859 [MAC-NR ] [D] [ 1459] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.711867 [NAS    ] [D] Attempting to select PLMN
05:20:13.711870 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.712659 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.712673 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1460, tti_jump=1
05:20:13.712683 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.712686 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.712711 [MAC    ] [D] [ 1460] Running MAC tti=1460
05:20:13.712714 [MAC    ] [D] [ 1460] Update Bj: lcid=0, Bj=0
05:20:13.712715 [MAC    ] [D] [ 1460] Update Bj: lcid=1, Bj=0
05:20:13.712722 [MAC    ] [D] [ 1460] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.712724 [MAC-NR ] [D] [ 1460] Running MAC tti=1460
05:20:13.712738 [MAC-NR ] [D] [ 1460] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []
05:20:13.712744 [NAS    ] [D] Attempting to select PLMN
05:20:13.712747 [STCK   ] [D] tti_tprof: duration=0 msec
05:20:13.712796 [PHY_LIB] [D] [ 1460]  PSS: id=2, peak_pos=350, peak_value=1.031625
05:20:13.712809 [PHY_LIB] [D] [ 1460]  SYNC ret=0 N_id_2=2 find_offset=0 frame_len=1920, pos=350 peak=1.03 threshold=3.00 CFO=-5.740 kHz
05:20:13.712816 [PHY_LIB] [I] [ 1460]  SYNC FIND: sf_idx=0, ret=0, peak_pos=350, peak_value=1.03, mean_cp_cfo=-0.38, mean_pss_cfo=0.00, total_cfo_khz=-5.7
05:20:13.712818 [PHY    ] [I] [    0] SYNC:  Waiting for PSS while trying to decode MIB (34/100)
05:20:13.712828 [PHY    ] [D] [    0] SYNC:  state=SYNC, tti=1461
05:20:13.713727 [PHY    ] [D] [    0] run_stack_tti: from recv
05:20:13.713740 [PHY    ] [D] [    0] run_stack_tti: calling stack tti=1461, tti_jump=1
05:20:13.713750 [PHY    ] [D] [    0] run_stack_tti: stack called
05:20:13.713753 [PHY    ] [D] [    0] SYNC:  received 1920 samples from radio
05:20:13.713780 [MAC    ] [D] [ 1461] Running MAC tti=1461
05:20:13.713783 [MAC    ] [D] [ 1461] Update Bj: lcid=0, Bj=0
05:20:13.713786 [MAC    ] [D] [ 1461] Update Bj: lcid=1, Bj=0
05:20:13.713794 [MAC    ] [D] [ 1461] RA:    INIT:   rar_window_start=-1, rar_window_length=-1
05:20:13.713797 [MAC-NR ] [D] [ 1461] Running MAC tti=1461
05:20:13.713806 [MAC-NR ] [D] [ 1461] nof_lcids_with_data=0, nof_lcgs_with_data=0, last_non_zero_lcg=-1 [] []

Thanks in advance!

andrepuschmann commented 2 years ago

The MIB SNR is very low ~0db. Your signal is just too weak.