COTS UE cannot connected to X310 gNB

[lgs96]

Issue Description

[Describe the issue in detail]
Huawei P40 Pro and Pixel 6a cannot be connected to the X310 gNB with GPSDO

Setup Details

[Specify details of the test setup. This would help us reproduce the problem reliably]
Ubuntu 22.04, USRP 2943R (X310), Leobodnar GPSDO (connected to external reference clock and PPS input)

Expected Behavior

COTS UE should be connceted

Actual Behaviour

Not connected and even no RACH is shown in the terminal. Below is the terminal logs.

Lower PHY in quad executor mode.

--== srsRAN gNB (commit 0b2702c) ==--

Connecting to AMF on 127.0.1.100:38412
Available radio types: uhd.
[INFO] [UHD] linux; GNU C++ version 11.4.0; Boost_107400; UHD_4.6.0.0-0ubuntu1~jammy1
[INFO] [LOGGING] Fastpath logging disabled at runtime.
Making USRP object with args 'type=x300,master_clock_rate=184.32e6,send_frame_size=8000,recv_frame_size=8000'
[INFO] [X300] X300 initialization sequence...
[DEBUG] [X300] Motherboard 0 has remote device ID: 1
[DEBUG] [X300] Setting up basic communication...
[DEBUG] [X300] Using FPGA version: 39.2 git hash: 6a990d9
[DEBUG] [X300] Loading values from EEPROM...
[DEBUG] [X300] Determining maximum frame size...
[INFO] [X300] Maximum frame size: 8000 bytes.
[DEBUG] [X300] Setting up RF frontend clocking...
[DEBUG] [X300] x300_clock_ctrl::set_clock_delay: Which=8, Requested=0.000000, Digital Taps=5, Half Shift=OFF, Analog Delay=0 (OFF), Coerced Delay=0.000000ns
[DEBUG] [X300] x300_clock_ctrl::set_clock_delay: Which=4, Requested=0.000000, Digital Taps=5, Half Shift=OFF, Analog Delay=0 (OFF), Coerced Delay=0.000000ns
[DEBUG] [X300] x300_clock_ctrl::set_clock_delay: Which=5, Requested=0.000000, Digital Taps=5, Half Shift=OFF, Analog Delay=0 (OFF), Coerced Delay=0.000000ns
[DEBUG] [X300] x300_clock_ctrl::set_clock_delay: Which=0, Requested=0.000000, Digital Taps=5, Half Shift=OFF, Analog Delay=0 (OFF), Coerced Delay=0.000000ns
[DEBUG] [X300] x300_clock_ctrl::set_clock_delay: Which=2, Requested=0.000000, Digital Taps=5, Half Shift=OFF, Analog Delay=0 (OFF), Coerced Delay=0.000000ns
[INFO] [X300] Radio 1x clock: 184.32 MHz
[DEBUG] [X300] Motherboard 0 has local device IDs:
[DEBUG] [X300] * 2
[DEBUG] [RFNOC::MGMT] Starting topology discovery from device[local]:2/sep:1
[DEBUG] [RFNOC::MGMT] Discovered node device:1/xport:1
[DEBUG] [RFNOC::MGMT] Initialized node device:1/xport:1
[DEBUG] [RFNOC::MGMT] Discovered node device:1/xbar:0
[DEBUG] [RFNOC::MGMT] Initialized node device:1/xbar:0
[DEBUG] [RFNOC::MGMT] Discovered node device:1/sep:0
[DEBUG] [RFNOC::MGMT] Initialized node device:1/sep:0
[DEBUG] [RFNOC::MGMT] Discovered node device:1/sep:1
[DEBUG] [RFNOC::MGMT] Initialized node device:1/sep:1
[DEBUG] [RFNOC::MGMT] Discovered node device:1/sep:2
[DEBUG] [RFNOC::MGMT] Initialized node device:1/sep:2
[DEBUG] [RFNOC::MGMT] Discovered node device:1/sep:3
[DEBUG] [RFNOC::MGMT] Initialized node device:1/sep:3
[DEBUG] [RFNOC::MGMT] Discovered node device:1/sep:4
[DEBUG] [RFNOC::MGMT] Initialized node device:1/sep:4
[DEBUG] [RFNOC::MGMT] Discovered node device:1/sep:5
[DEBUG] [RFNOC::MGMT] Initialized node device:1/sep:5
[DEBUG] [RFNOC::MGMT] The following endpoints are reachable from device[local]:2/sep:1
[DEBUG] [RFNOC::MGMT] * 1:0
[DEBUG] [RFNOC::MGMT] * 1:1
[DEBUG] [RFNOC::MGMT] * 1:2
[DEBUG] [RFNOC::MGMT] * 1:3
[DEBUG] [RFNOC::MGMT] * 1:4
[DEBUG] [RFNOC::MGMT] * 1:5
[DEBUG] [RFNOC::LSM] Adding node device:1/xport:0 to topology graph outside of discovery.
[DEBUG] [RFNOC::LSM] Adding transport adapter on xbar port 0
[DEBUG] [RFNOC::GRAPH] Connecting the Host to Endpoint 1:0 through Adapter 0 (0 = no preference)...
[DEBUG] [RFNOC::MGMT] Throttling stream endpoint to 100% (0x0)
[DEBUG] [RFNOC::MGMT] Bound stream endpoint with Addr=(1,0) to EPID=2
[DEBUG] [RFNOC] Started thread uhd_ctrl_ep0001 to process messages control messages on EPID 1
[DEBUG] [RFNOC::MGMT] Established a route from EPID=1 (SW) to EPID=2
[DEBUG] [RFNOC] Created ctrlport endpoint for port 0 on EPID 1
[DEBUG] [RFNOC::GRAPH] Connection to Endpoint 1:0 completed through Device 2. Using EPIDs 1 -> 2.
[DEBUG] [RFNOC] Created ctrlport endpoint for port 2 on EPID 1
[DEBUG] [0/DUC#0] Checking compat number for FPGA component 0/DUC#0': Expecting 0.1, actual: 0.1. [DEBUG] [0/DUC#0] Loading DUC with 3 halfbands and max CIC interpolation 255 [DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/DUC#0 (NOC ID=d0c00000) [DEBUG] [RFNOC] Created ctrlport endpoint for port 3 on EPID 1 [DEBUG] [0/DDC#0] Checking compat number for FPGA component 0/DDC#0': Expecting 0.1, actual: 0.1.
[DEBUG] [0/DDC#0] Loading DDC with 3 halfbands and max CIC decimation 255
[DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/DDC#0 (NOC ID=ddc00000)
[DEBUG] [RFNOC] Created ctrlport endpoint for port 4 on EPID 1
[DEBUG] [0/Radio#0] Checking compat number for FPGA component 0/Radio#0': Expecting 0.1, actual: 0.1. [DEBUG] [0/Radio#0] ADC capture delay self-cal done (Tap=15, Window=25, TapDelay=78.125ps, Iter=1) [DEBUG] [0/Radio#0] Actual sample rate: 184.32 Msps. [DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/Radio#0 (NOC ID=12ad1000) [DEBUG] [RFNOC] Created ctrlport endpoint for port 5 on EPID 1 [DEBUG] [0/DUC#1] Checking compat number for FPGA component 0/DUC#1': Expecting 0.1, actual: 0.1.
[DEBUG] [0/DUC#1] Loading DUC with 3 halfbands and max CIC interpolation 255
[DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/DUC#1 (NOC ID=d0c00000)
[DEBUG] [RFNOC] Created ctrlport endpoint for port 6 on EPID 1
[DEBUG] [0/DDC#1] Checking compat number for FPGA component 0/DDC#1': Expecting 0.1, actual: 0.1. [DEBUG] [0/DDC#1] Loading DDC with 3 halfbands and max CIC decimation 255 [DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/DDC#1 (NOC ID=ddc00000) [DEBUG] [RFNOC] Created ctrlport endpoint for port 7 on EPID 1 [DEBUG] [0/Radio#1] Checking compat number for FPGA component 0/Radio#1': Expecting 0.1, actual: 0.1.
[DEBUG] [0/Radio#1] ADC capture delay self-cal done (Tap=20, Window=22, TapDelay=78.125ps, Iter=1)
[DEBUG] [0/Radio#1] Actual sample rate: 184.32 Msps.
[DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/Radio#1 (NOC ID=12ad1000)
[DEBUG] [RFNOC] Created ctrlport endpoint for port 8 on EPID 1
[DEBUG] [0/Replay#0] Checking compat number for FPGA component `0/Replay#0': Expecting 1.2, actual: 1.2.
[DEBUG] [RFNOC::BLOCK_CONTAINER] Registering block: 0/Replay#0 (NOC ID=4e91a000)
[DEBUG] [0/DDC#1] Not setting frequency until sampling rate is set.
[DEBUG] [0/DDC#1] Not setting frequency until sampling rate is set.
[DEBUG] [0/DUC#1] Not setting frequency until sampling rate is set.
[DEBUG] [0/DDC#0] Not setting frequency until sampling rate is set.
[DEBUG] [0/DDC#0] Not setting frequency until sampling rate is set.
[DEBUG] [0/DUC#0] Not setting frequency until sampling rate is set.
[DEBUG] [0/Radio#0] Running ADC self-cal...
[DEBUG] [0/Radio#1] Running ADC self-cal...
[DEBUG] [MB_CTRL] Synchronizing 1 timekeepers
[DEBUG] [CONVERT] get_converter: For converter ID: conversion ID
Input format: fc32
Num inputs: 1
Output format: sc16_chdr
Num outputs: 1
Using best available prio: 3
[DEBUG] [RFNOC::MGMT] Established a route from EPID=3 (SW) to EPID=2
[DEBUG] [RFNOC::MGMT] Established a route from EPID=3 (SW) to EPID=2
[DEBUG] [RFNOC::MGMT] Finished TX stream setup for EPID=2
[DEBUG] [MULTI_USRP] Inconsistent TX rates when creating streamer! Harmonizing to 2.304e+07
[WARNING] [0/Radio#0] Attempting to set tick rate to 0. Skipping.
[DEBUG] [CONVERT] get_converter: For converter ID: conversion ID
Input format: sc16_chdr
Num inputs: 1
Output format: fc32
Num outputs: 1
Using best available prio: 3
[DEBUG] [RFNOC::MGMT] Established a route from EPID=4 (SW) to EPID=2
[DEBUG] [RFNOC::MGMT] Throttling stream endpoint to 100% (0x0)
[DEBUG] [RFNOC::MGMT] Initiated RX stream setup for EPID=2
[DEBUG] [RFNOC::MGMT] Finished RX stream setup for EPID=2
[DEBUG] [0/Radio#0] spp value 2032 exceeds MTU of 8000! Coercing to 1996
Cell pci=1, bw=20 MHz, dl_arfcn=500001 (n41), dl_freq=2500.005 MHz, dl_ssb_arfcn=498510, ul_freq=2500.005 MHz

==== gNodeB started ===
Type to view trace
Could not transmit RAR within the window=[671.0..672.0), prach_slot=670.9, slot_tx=672.0
Could not transmit RAR within the window=[391.0..392.0), prach_slot=390.9, slot_tx=392.0
Could not transmit RAR within the window=[629.0..630.0), prach_slot=628.9, slot_tx=630.0
Could not transmit RAR within the window=[933.0..934.0), prach_slot=932.9, slot_tx=934.0
Could not transmit RAR within the window=[90.0..91.0), prach_slot=89.9, slot_tx=91.0
Could not transmit RAR within the window=[329.0..330.0), prach_slot=328.9, slot_tx=330.0
Could not transmit RAR within the window=[608.0..609.0), prach_slot=607.9, slot_tx=609.0
Late: 0; Underflow: 1; Overflow: 0;
Late: 0; Underflow: 1; Overflow: 0;
Late: 0; Underflow: 1; Overflow: 0;
Late: 0; Underflow: 1; Overflow: 0;
Could not transmit RAR within the window=[56.0..57.0), prach_slot=55.9, slot_tx=57.0
Late: 0; Underflow: 1; Overflow: 0;
Could not transmit RAR within the window=[447.0..448.0), prach_slot=446.9, slot_tx=448.0
^CStopping ..
gnb_cots.zip

Steps to reproduce the problem

gNB commit version: 0b2702c
gNB config: attached

Additional Information

[Any additional information, configuration or data that might be necessary to reproduce the issue]

[robertfalkenberg]

Could you please enable MAC pcap and NGAP pcap, repeat your experiment and upload logs+pcaps here?

[lgs96]

log.txt
pcap.zip

I checked the pcap, but no packet is captured.. Why?
This is not an wireless signal issues since I run srsLTE with COTS UE in the same bands.

[lgs96]

I'm sorry but I find that there were messages when I run it in n78.
But I cannot understand these logs. Here's my logs.

I find that the Open5GS log shows the rejection of my UE (Even though this works in srsLTE)

ow 0 (../src/amf/context.c:2557)
02/19 20:16:50.550: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1709)
02/19 20:16:53.913: [sbi] WARNING: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] HTTP response error [404] (../lib/sbi/nf-sm.c:277)
02/19 20:16:53.913: [sbi] INFO: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] NF de-registered (../lib/sbi/nf-sm.c:248)
02/19 20:16:55.913: [sbi] WARNING: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] Retry registration with NRF (../lib/sbi/nf-sm.c:405)
02/19 20:16:55.913: [sbi] INFO: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] NF registered [Heartbeat:10s] (../lib/sbi/nf-sm.c:221)
02/19 20:16:55.914: [sbi] INFO: [bcc0984c-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914100-05:00 [duration:86400,validity:86399.999523,patch:43199.999761] (../lib/sbi/nnrf-handler.c:708)
02/19 20:16:55.914: [sbi] INFO: [bcc09b3a-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914173-05:00 [duration:86400,validity:86399.999579,patch:43199.999789] (../lib/sbi/nnrf-handler.c:708)
02/19 20:16:55.914: [sbi] INFO: [bcc09f18-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914272-05:00 [duration:86400,validity:86399.999634,patch:43199.999817] (../lib/sbi/nnrf-handler.c:708)
02/19 20:16:55.914: [sbi] INFO: [bcc0a0c6-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914315-05:00 [duration:86400,validity:86399.999612,patch:43199.999806] (../lib/sbi/nnrf-handler.c:708)
02/19 20:16:55.914: [sbi] INFO: [bcc0a1ac-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914338-05:00 [duration:86400,validity:86399.999508,patch:43199.999754] (../lib/sbi/nnrf-handler.c:708)
02/19 20:16:55.914: [sbi] INFO: [bcc0a54e-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914430-05:00 [duration:86400,validity:86399.999579,patch:43199.999789] (../lib/sbi/nnrf-handler.c:708)
02/19 20:16:55.914: [sbi] INFO: [bcc0a62a-cf8d-41ee-a71c-1191f27455cd] Subscription created until 2024-02-20T20:16:55.914450-05:00 [duration:86400,validity:86399.999570,patch:43199.999785] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:17.820: [amf] INFO: gNB-N2[127.0.0.1] connection refused!!! (../src/amf/amf-sm.c:793)
02/19 20:17:17.820: [amf] INFO: [Removed] Number of gNBs is now 0 (../src/amf/context.c:1258)
02/19 20:17:21.076: [amf] INFO: gNB-N2 accepted[127.0.0.1]:45432 in ng-path module (../src/amf/ngap-sctp.c:113)
02/19 20:17:21.076: [amf] INFO: gNB-N2 accepted[127.0.0.1] in master_sm module (../src/amf/amf-sm.c:741)
02/19 20:17:21.079: [amf] INFO: [Added] Number of gNBs is now 1 (../src/amf/context.c:1231)
02/19 20:17:21.079: [amf] INFO: gNB-N2[127.0.0.1] max_num_of_ostreams : 30 (../src/amf/amf-sm.c:780)
02/19 20:17:33.703: [amf] INFO: InitialUEMessage (../src/amf/ngap-handler.c:401)
02/19 20:17:33.703: [amf] INFO: [Added] Number of gNB-UEs is now 1 (../src/amf/context.c:2550)
02/19 20:17:33.703: [amf] INFO:     RAN_UE_NGAP_ID[0] AMF_UE_NGAP_ID[26] TAC[7] CellID[0x19b0] (../src/amf/ngap-handler.c:562)
02/19 20:17:33.703: [amf] INFO: [suci-0-001-01-0-0-0-0000000001] Unknown UE by SUCI (../src/amf/context.c:1835)
02/19 20:17:33.703: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1616)
02/19 20:17:33.703: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1165)
02/19 20:17:33.703: [gmm] INFO: [suci-0-001-01-0-0-0-0000000001]    SUCI (../src/amf/gmm-handler.c:166)
02/19 20:17:33.763: [gmm] ERROR: [suci-0-001-01-0-0-0-0000000001] HTTP response error [500] (../src/amf/gmm-sm.c:1675)
02/19 20:17:33.763: [amf] WARNING: [suci-0-001-01-0-0-0-0000000001] Registration reject [9] (../src/amf/nas-path.c:219)
02/19 20:17:33.884: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1698)
02/19 20:17:33.884: [amf] INFO:     RAN_UE_NGAP_ID[0] AMF_UE_NGAP_ID[26] (../src/amf/ngap-handler.c:1699)
02/19 20:17:33.884: [amf] INFO:     SUCI[suci-0-001-01-0-0-0-0000000001] (../src/amf/ngap-handler.c:1702)
02/19 20:17:33.884: [amf] INFO: [Removed] Number of gNB-UEs is now 0 (../src/amf/context.c:2557)
02/19 20:17:33.884: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1709)
02/19 20:17:34.008: [amf] INFO: InitialUEMessage (../src/amf/ngap-handler.c:401)
02/19 20:17:34.008: [amf] INFO: [Added] Number of gNB-UEs is now 1 (../src/amf/context.c:2550)
02/19 20:17:34.008: [amf] INFO:     RAN_UE_NGAP_ID[1] AMF_UE_NGAP_ID[27] TAC[7] CellID[0x19b0] (../src/amf/ngap-handler.c:562)
02/19 20:17:34.008: [amf] INFO: [suci-0-001-01-0-0-0-0000000001] Unknown UE by SUCI (../src/amf/context.c:1835)
02/19 20:17:34.008: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1616)
02/19 20:17:34.008: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1165)
02/19 20:17:34.008: [gmm] INFO: [suci-0-001-01-0-0-0-0000000001]    SUCI (../src/amf/gmm-handler.c:166)
02/19 20:17:34.009: [gmm] ERROR: [suci-0-001-01-0-0-0-0000000001] HTTP response error [500] (../src/amf/gmm-sm.c:1675)
02/19 20:17:34.009: [amf] WARNING: [suci-0-001-01-0-0-0-0000000001] Registration reject [9] (../src/amf/nas-path.c:219)
02/19 20:17:34.129: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1698)
02/19 20:17:34.129: [amf] INFO:     RAN_UE_NGAP_ID[1] AMF_UE_NGAP_ID[27] (../src/amf/ngap-handler.c:1699)
02/19 20:17:34.129: [amf] INFO:     SUCI[suci-0-001-01-0-0-0-0000000001] (../src/amf/ngap-handler.c:1702)
02/19 20:17:34.129: [amf] INFO: [Removed] Number of gNB-UEs is now 0 (../src/amf/context.c:2557)
02/19 20:17:34.129: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1709)
02/19 20:17:34.263: [amf] INFO: InitialUEMessage (../src/amf/ngap-handler.c:401)
02/19 20:17:34.263: [amf] INFO: [Added] Number of gNB-UEs is now 1 (../src/amf/context.c:2550)
02/19 20:17:34.263: [amf] INFO:     RAN_UE_NGAP_ID[2] AMF_UE_NGAP_ID[28] TAC[7] CellID[0x19b0] (../src/amf/ngap-handler.c:562)
02/19 20:17:34.263: [amf] INFO: [suci-0-001-01-0-0-0-0000000001] Unknown UE by SUCI (../src/amf/context.c:1835)
02/19 20:17:34.263: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1616)
02/19 20:17:34.263: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1165)
02/19 20:17:34.263: [gmm] INFO: [suci-0-001-01-0-0-0-0000000001]    SUCI (../src/amf/gmm-handler.c:166)
02/19 20:17:34.263: [gmm] ERROR: [suci-0-001-01-0-0-0-0000000001] HTTP response error [500] (../src/amf/gmm-sm.c:1675)
02/19 20:17:34.263: [amf] WARNING: [suci-0-001-01-0-0-0-0000000001] Registration reject [9] (../src/amf/nas-path.c:219)
02/19 20:17:34.383: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1698)
02/19 20:17:34.383: [amf] INFO:     RAN_UE_NGAP_ID[2] AMF_UE_NGAP_ID[28] (../src/amf/ngap-handler.c:1699)
02/19 20:17:34.383: [amf] INFO:     SUCI[suci-0-001-01-0-0-0-0000000001] (../src/amf/ngap-handler.c:1702)
02/19 20:17:34.383: [amf] INFO: [Removed] Number of gNB-UEs is now 0 (../src/amf/context.c:2557)
02/19 20:17:34.383: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1709)
02/19 20:17:34.583: [amf] INFO: InitialUEMessage (../src/amf/ngap-handler.c:401)
02/19 20:17:34.583: [amf] INFO: [Added] Number of gNB-UEs is now 1 (../src/amf/context.c:2550)
02/19 20:17:34.583: [amf] INFO:     RAN_UE_NGAP_ID[3] AMF_UE_NGAP_ID[29] TAC[7] CellID[0x19b0] (../src/amf/ngap-handler.c:562)
02/19 20:17:34.583: [amf] INFO: [suci-0-001-01-0-0-0-0000000001] Unknown UE by SUCI (../src/amf/context.c:1835)
02/19 20:17:34.583: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1616)
02/19 20:17:34.583: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1165)
02/19 20:17:34.583: [gmm] INFO: [suci-0-001-01-0-0-0-0000000001]    SUCI (../src/amf/gmm-handler.c:166)
02/19 20:17:34.583: [gmm] ERROR: [suci-0-001-01-0-0-0-0000000001] HTTP response error [500] (../src/amf/gmm-sm.c:1675)
02/19 20:17:34.583: [amf] WARNING: [suci-0-001-01-0-0-0-0000000001] Registration reject [9] (../src/amf/nas-path.c:219)
02/19 20:17:34.703: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1698)
02/19 20:17:34.703: [amf] INFO:     RAN_UE_NGAP_ID[3] AMF_UE_NGAP_ID[29] (../src/amf/ngap-handler.c:1699)
02/19 20:17:34.703: [amf] INFO:     SUCI[suci-0-001-01-0-0-0-0000000001] (../src/amf/ngap-handler.c:1702)
02/19 20:17:34.704: [amf] INFO: [Removed] Number of gNB-UEs is now 0 (../src/amf/context.c:2557)
02/19 20:17:34.704: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1709)
02/19 20:17:34.824: [amf] INFO: InitialUEMessage (../src/amf/ngap-handler.c:401)
02/19 20:17:34.824: [amf] INFO: [Added] Number of gNB-UEs is now 1 (../src/amf/context.c:2550)
02/19 20:17:34.824: [amf] INFO:     RAN_UE_NGAP_ID[4] AMF_UE_NGAP_ID[30] TAC[7] CellID[0x19b0] (../src/amf/ngap-handler.c:562)
02/19 20:17:34.824: [amf] INFO: [suci-0-001-01-0-0-0-0000000001] Unknown UE by SUCI (../src/amf/context.c:1835)
02/19 20:17:34.824: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1616)
02/19 20:17:34.824: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1165)
02/19 20:17:34.824: [gmm] INFO: [suci-0-001-01-0-0-0-0000000001]    SUCI (../src/amf/gmm-handler.c:166)
02/19 20:17:34.825: [gmm] ERROR: [suci-0-001-01-0-0-0-0000000001] HTTP response error [500] (../src/amf/gmm-sm.c:1675)
02/19 20:17:34.825: [amf] WARNING: [suci-0-001-01-0-0-0-0000000001] Registration reject [9] (../src/amf/nas-path.c:219)
02/19 20:17:34.963: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1698)
02/19 20:17:34.963: [amf] INFO:     RAN_UE_NGAP_ID[4] AMF_UE_NGAP_ID[30] (../src/amf/ngap-handler.c:1699)
02/19 20:17:34.963: [amf] INFO:     SUCI[suci-0-001-01-0-0-0-0000000001] (../src/amf/ngap-handler.c:1702)
02/19 20:17:34.963: [amf] INFO: [Removed] Number of gNB-UEs is now 0 (../src/amf/context.c:2557)
02/19 20:17:34.963: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1709)
02/19 20:17:35.938: [sbi] WARNING: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] HTTP response error [404] (../lib/sbi/nf-sm.c:277)
02/19 20:17:35.938: [sbi] INFO: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] NF de-registered (../lib/sbi/nf-sm.c:248)
02/19 20:17:37.940: [sbi] WARNING: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] Retry registration with NRF (../lib/sbi/nf-sm.c:405)
02/19 20:17:37.941: [sbi] INFO: [d38a46fa-cf8c-41ee-943d-83b7ebc07540] NF registered [Heartbeat:10s] (../lib/sbi/nf-sm.c:221)
02/19 20:17:37.941: [sbi] INFO: [d5cd6f7c-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941292-05:00 [duration:86400,validity:86399.999582,patch:43199.999791] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:37.941: [sbi] INFO: [d5cd72d8-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941374-05:00 [duration:86400,validity:86399.999645,patch:43199.999822] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:37.941: [sbi] INFO: [d5cd7454-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941413-05:00 [duration:86400,validity:86399.999640,patch:43199.999820] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:37.941: [sbi] INFO: [d5cd7670-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941465-05:00 [duration:86400,validity:86399.999636,patch:43199.999818] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:37.941: [sbi] INFO: [d5cd7abc-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941576-05:00 [duration:86400,validity:86399.999726,patch:43199.999863] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:37.941: [sbi] INFO: [d5cd7bf2-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941607-05:00 [duration:86400,validity:86399.999731,patch:43199.999865] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:37.941: [sbi] INFO: [d5cd7eae-cf8d-41ee-8726-716750cff03e] Subscription created until 2024-02-20T20:17:37.941677-05:00 [duration:86400,validity:86399.999724,patch:43199.999862] (../lib/sbi/nnrf-handler.c:708)
02/19 20:17:41.371: [amf] INFO: gNB-N2[127.0.0.1] connection refused!!! (../src/amf/amf-sm.c:793)
02/19 20:17:41.371: [amf] INFO: [Removed] Number of gNBs is now 0 (../src/amf/context.c:1258)

pcap2.zip

[pgawlowicz]

did you add the UE to the Open5gs subscriber database? there is a message in the logs:

02/19 20:17:34.583: [amf] INFO: [suci-0-001-01-0-0-0-0000000001] Unknown UE by SUCI (../src/amf/context.c:1835)

[lgs96]

@pgawlowicz Thank you for your comment! I checked it works with srsLTE + Open5GS mme, which shares the registered subscriber list with Open5GS AMF.... So I guess that the problem might not from the subscriber database, but if there is any additional things to put it in subscriber list or logs that I should provide to verify this, I'll be pleased to do that.

[pgawlowicz]

There is clearly an issue with the Core network not able to recognise the UE.

Could you verify that the subscriber database is properly populated?

[lgs96]

Hi, I attach the screenshot of subscriber in open5gs.

I find that there may needs another DNN/APN option, but I could not find how to add another DNN/APN option.

If there's any problem, please notify me.

This same setting works in the srsLTE with Open5GS and same USIM used for srsRAN Project.

[pgawlowicz]

If you click on edit (pencil) and scroll down, you can find DNN/APN option.

[lgs96]

@pgawlowicz Thank you. But I mean, I need to add new DNN/APN in addition to the existing DNN/APN. However, only one DNN/APN is allowed to be added.

[pgawlowicz]

could you share your Open5GS configs?

[lgs96]

@pgawlowicz How can I share the Open5GS configs?

[pgawlowicz]

they should be at /etc/open5gs/ if you installed from source

[lgs96]

Hi, I attach the use lists.

Current Mongosh Log ID: 65de5fb490c04344313efaeb
Connecting to: mongodb://localhost/open5gs?directConnection=true&serverSelectionTimeoutMS=2000&appName=mongosh+2.1.1
Using MongoDB: 6.0.12
Using Mongosh: 2.1.1

For mongosh info see: https://docs.mongodb.com/mongodb-shell/

---

The server generated these startup warnings when booting
2024-02-27T13:07:56.456-05:00: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem
2024-02-27T13:07:56.720-05:00: Access control is not enabled for the database. Read and write access to data and configuration is unrestricted
2024-02-27T13:07:56.720-05:00: vm.max_map_count is too low

[
{
_id: ObjectId('65a7767f3fcc46499263c6cb'),
ambr: { downlink: { value: 1, unit: 3 }, uplink: { value: 1, unit: 3 } },
schema_version: 1,
msisdn: [],
imeisv: [ '3575075510111837' ],
mme_host: [ 'mme.localdomain' ],
mme_realm: [ 'localdomain' ],
purge_flag: [ false ],
access_restriction_data: 32,
subscriber_status: 0,
operator_determined_barring: 0,
network_access_mode: 0,
subscribed_rau_tau_timer: 12,
imsi: '001010000000001',
security: {
k: 'fec86ba6eb707ed08905757b1bb44b8f',
amf: '8000',
op: null,
opc: 'C42449363BBAD02B66D16BC975D77CC1',
sqn: Long('28012')
},
slice: [
{
_id: ObjectId('65a7767f3fcc46499263c6cc'),
sst: 1,
default_indicator: true,
session: [
{
qos: {
arp: {
priority_level: 8,
pre_emption_capability: 1,
pre_emption_vulnerability: 1
},
index: 9
},
ambr: {
downlink: { value: 1, unit: 3 },
uplink: { value: 1, unit: 3 }
},
_id: ObjectId('65a7767f3fcc46499263c6cd'),
name: 'internet',
type: 3,
pcc_rule: []
}
]
}
],
__v: 0,
mme_timestamp: Long('1708392268286688')
},
{
_id: ObjectId('65a8c52823005d321665f622'),
ambr: { downlink: { value: 1, unit: 3 }, uplink: { value: 1, unit: 3 } },
schema_version: 1,
msisdn: [],
imeisv: [ '3569889545444208' ],
mme_host: [ 'mme.localdomain' ],
mme_realm: [ 'localdomain' ],
purge_flag: [ false ],
access_restriction_data: 32,
subscriber_status: 0,
operator_determined_barring: 0,
network_access_mode: 0,
subscribed_rau_tau_timer: 12,
imsi: '001010000090213',
security: {
k: 'fec86ba6eb707ed08905757b1bb44b8f',
amf: '8000',
op: null,
opc: 'C42449363BBAD02B66D16BC975D77CC1',
sqn: Long('384')
},
slice: [
{
_id: ObjectId('65a8c52823005d321665f623'),
sst: 1,
default_indicator: true,
session: [
{
qos: {
arp: {
priority_level: 8,
pre_emption_capability: 1,
pre_emption_vulnerability: 1
},
index: 9
},
ambr: {
downlink: { value: 1, unit: 3 },
uplink: { value: 1, unit: 3 }
},
_id: ObjectId('65a8c52823005d321665f624'),
name: 'internet',
type: 1,
pcc_rule: []
}
]
}
],
__v: 0,
mme_timestamp: Long('1705560814629899')
},
{
_id: ObjectId('65a8c992cbffb8f545a53891'),
ambr: { downlink: { value: 1, unit: 3 }, uplink: { value: 1, unit: 3 } },
schema_version: 1,
msisdn: [],
imeisv: [],
mme_host: [],
mme_realm: [],
purge_flag: [],
access_restriction_data: 32,
subscriber_status: 0,
operator_determined_barring: 0,
network_access_mode: 0,
subscribed_rau_tau_timer: 12,
imsi: '999700000090210',
security: {
k: '22B9B2B45105CEBA31B5555BEF382A56',
amf: '8000',
op: null,
opc: '61D9F790D95ACBF28CE2A95593EBAB1D'
},
slice: [
{
_id: ObjectId('65a8c992cbffb8f545a53892'),
sst: 1,
default_indicator: true,
session: [
{
qos: {
arp: {
priority_level: 8,
pre_emption_capability: 1,
pre_emption_vulnerability: 1
},
index: 9
},
ambr: {
downlink: { value: 1, unit: 3 },
uplink: { value: 1, unit: 3 }
},
_id: ObjectId('65a8c992cbffb8f545a53893'),
name: 'internet',
type: 3,
pcc_rule: []
}
]
}
],
__v: 0
},
{
_id: ObjectId('65a8d663c5b4730ac4281686'),
ambr: { downlink: { value: 1, unit: 3 }, uplink: { value: 1, unit: 3 } },
schema_version: 1,
msisdn: [],
imeisv: '8628490443879833',
mme_host: 'mme.localdomain',
mme_realm: 'localdomain',
purge_flag: false,
access_restriction_data: 32,
subscriber_status: 0,
operator_determined_barring: 0,
network_access_mode: 0,
subscribed_rau_tau_timer: 12,
imsi: '001010000000003',
security: {
k: 'fec86ba6eb707ed08905757b1bb44b8f',
amf: '8000',
op: null,
opc: 'C42449363BBAD02B66D16BC975D77CC1',
sqn: Long('3332')
},
slice: [
{
_id: ObjectId('65a8d663c5b4730ac4281687'),
sst: 1,
default_indicator: true,
session: [
{
qos: {
arp: {
priority_level: 8,
pre_emption_capability: 1,
pre_emption_vulnerability: 1
},
index: 9
},
ambr: {
downlink: { value: 1, unit: 3 },
uplink: { value: 1, unit: 3 }
},
_id: ObjectId('65a8d663c5b4730ac4281688'),
name: 'internet',
type: 3,
pcc_rule: []
}
]
}
],
__v: 0,
mme_timestamp: Long('1708254296049727')
},
{
_id: ObjectId('65a8d9b4c5b4730ac42816a5'),
ambr: { downlink: { value: 1, unit: 3 }, uplink: { value: 1, unit: 3 } },
schema_version: 1,
msisdn: [],
imeisv: '3574504614778401',
mme_host: 'mme.localdomain',
mme_realm: 'localdomain',
purge_flag: false,
access_restriction_data: 32,
subscriber_status: 0,
operator_determined_barring: 0,
network_access_mode: 0,
subscribed_rau_tau_timer: 12,
imsi: '001010000000002',
security: {
k: 'fec86ba6eb707ed08905757b1bb44b8f',
amf: '8000',
op: null,
opc: 'C42449363BBAD02B66D16BC975D77CC1',
sqn: Long('800')
},
slice: [
{
_id: ObjectId('65a8d9b4c5b4730ac42816a6'),
sst: 1,
default_indicator: true,
session: [
{
qos: {
arp: {
priority_level: 8,
pre_emption_capability: 1,
pre_emption_vulnerability: 1
},
index: 9
},
ambr: {
downlink: { value: 1, unit: 3 },
uplink: { value: 1, unit: 3 }
},
_id: ObjectId('65a8d9b4c5b4730ac42816a7'),
name: 'internet',
type: 3,
pcc_rule: []
}
]
}
],
__v: 0,
mme_timestamp: Long('1708237917461392')
}
]

[pgawlowicz]

Please check Open5GS tutorial to find out where the configs are : https://open5gs.org/open5gs/docs/guide/01-quickstart/

[achkonsa]

sorry，same error happens to me,
03/15 15:17:43.167: [amf] INFO: [suci-0-001-01-0000-0-0-0000000000] Unknown UE by SUCI (../src/amf/context.c:1839)
03/15 15:17:43.167: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1620)
03/15 15:17:43.167: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1165)
03/15 15:17:43.167: [gmm] INFO: [suci-0-001-01-0000-0-0-0000000000] SUCI (../src/amf/gmm-handler.c:172)
03/15 15:17:43.194: [gmm] ERROR: [suci-0-001-01-0000-0-0-0000000000] HTTP response error [400] (../src/amf/gmm-sm.c:1715)
03/15 15:17:43.194: [amf] WARNING: [suci-0-001-01-0000-0-0-0000000000] Registration reject [95] (../src/amf/nas-path.c:206)
03/15 15:17:43.373: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1696)
could you help me through this error......this error has troubled me many dayssssssss :)

I am pretty sure the UE ipv4 and SMF ipv4 is correct....:)

[pgawlowicz]

Are you sure that the USIM authentication algorithm is milenage? Open5gs supports only this one.

[achkonsa]

First of all, I just wanna say thank you thank you thank you for answering me.
And I am sorry. I dont really know how could I check if the USIM authentication algorithm is milenage. Could you please tell me? :)

[pgawlowicz]

You can ask your SIM card provider, or check it with a SIM card reader.
You might be interested in checking this discussion: #503

[achkonsa]

Thank you so much. Let me have a check. I use srsRAN_4G as the UE, I dont know if it has any difference between the VM and actual phone...

[pgawlowicz]

could you post your configs here?

[achkonsa]

REALLY REALLY Thank you so much for being so patient.
AMFconfig.txt
GNBconfig.txt
UEconfig.txt
I hope these can be helpful. :)

[pgawlowicz]

hi @achkonsa, any update on this issue?

[achkonsa]

Sure, my partner try it on another server. He encounters the same HTTP response error, but his code is [403], mine is [400]. He restarts the AMF SMF UPF gnb and UE and it works.
Specifically, when "HTTP response error" occurs, STOP and RESTART: AMF SMF UPF gnb UE one by one, then it works.
BUT before this, we meet the question: "AMF: [gmm]Non cleartext IEs is included", then we solve it as here.
By the way, we use the Version 2.6.6 of open5gs. It seems that some format changes in the configuration files(such as amf.yaml) between v2.6.6 and v2.7.0.
Thanks thanks thanks for your caring and asking. And wish it be helpful to you. :)