search

srsran / srsRAN_Project

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

"Received RRC Release" at UE in ZMQ mode(already set inactivity_timer: 7200) #860

Open liumr3 opened 1 month ago

liumr3 commented 1 month ago

Issue Description

following the turorials https://docs.srsran.com/projects/project/en/latest/tutorials/source/srsUE/source/index.html, I test the ZMQ mode. I run 

sudo gnb -c gnb_zmq.yaml

it shows like this:

--== srsRAN gNB (commit e73b46182) ==--

The PRACH detector will not meet the performance requirements with the configuration {Format 0, ZCZ 0, SCS 1.25kHz, Rx ports 1}.
Lower PHY in executor blocking mode.
Available radio types: zmq.
Cell pci=1, bw=20 MHz, 1T1R, dl_arfcn=368500 (n3), dl_freq=1842.5 MHz, dl_ssb_arfcn=368410, ul_freq=1747.5 MHz

N2: Connection to AMF on 10.53.1.2:38412 completed
==== gNB started ===
Type <h> to view help

then i run

sudo ip netns add ue1

everything is ok

then i run

sudo srsue ue_rf.conf

it shows like this:

Active RF plugins: libsrsran_rf_zmq.so
Inactive RF plugins: 
Reading configuration file /ue_zmq.conf...

Built in Release mode using commit ec29b0c1f on branch master.

Opening 1 channels in RF device=zmq with args=tx_port=tcp://127.0.0.1:2001,rx_port=tcp://127.0.0.1:2000,base_srate=23.04e6
Supported RF device list: zmq file
CHx base_srate=23.04e6
Current sample rate is 1.92 MHz with a base rate of 23.04 MHz (x12 decimation)
CH0 rx_port=tcp://127.0.0.1:2000
CH0 tx_port=tcp://127.0.0.1:2001
Current sample rate is 23.04 MHz with a base rate of 23.04 MHz (x1 decimation)
Current sample rate is 23.04 MHz with a base rate of 23.04 MHz (x1 decimation)
Waiting PHY to initialize ... done!
Attaching UE...
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=1134
Random Access Complete.     c-rnti=0x4601, ta=0
RRC Connected
Received RRC Release

the received RRC Release, I have already set the cu_cp: inactivity_timer: 7200 in gnb_zmq.yaml

Setup Details

CPU: Intel Core i9-13900H Ubuntu: 22.04 srsran commit: https://github.com/srsran/srsRAN_Project/commit/e73b4618204151e6b95c142bec5798f5bc21b2b2 srs4g commit: https://github.com/srsran/srsRAN_4G/commit/ec29b0c1ff79cebcbe66caa6d6b90778261c42b8

Expected Behavior

the right show maybe like this:


Attaching UE...
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=2094
Random Access Complete.     c-rnti=0x4602, ta=0
RRC Connected
PDU Session Establishment successful. IP: 10.45.1.2
RRC NR reconfiguration successful.

Actual Behaviour


Attaching UE...
Random Access Transmission: prach_occasion=0, preamble_index=0, ra-rnti=0x39, tti=1134
Random Access Complete.     c-rnti=0x4601, ta=0
RRC Connected
Received RRC Release
pgawlowicz commented 1 month ago

could you send your log files (gnb, srsue and core network)?

liumr3 commented 1 month ago

could you send your log files (gnb, srsue and core network)?


2024-10-14T08:08:59.822377 [PHY1-NR] [I] [ 5242] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5246
2024-10-14T08:08:59.843419 [PHY1-NR] [I] [ 5262] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5266
2024-10-14T08:08:59.864463 [PHY1-NR] [I] [ 5282] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5286
2024-10-14T08:08:59.885558 [PHY1-NR] [I] [ 5302] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5306
2024-10-14T08:08:59.906740 [PHY1-NR] [I] [ 5322] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5326
2024-10-14T08:08:59.928309 [PHY1-NR] [I] [ 5342] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5346
2024-10-14T08:08:59.949557 [PHY1-NR] [I] [ 5362] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5366
2024-10-14T08:08:59.970892 [PHY1-NR] [I] [ 5382] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5386
2024-10-14T08:08:59.992069 [PHY1-NR] [I] [ 5402] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5406
2024-10-14T08:09:00.013168 [PHY1-NR] [I] [ 5422] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5426
2024-10-14T08:09:00.034322 [PHY1-NR] [I] [ 5442] PUCCH: cc=0, f=2 prb=2:1 symb=4:2 rnti=0x4601 cqi=15 , tti_tx=5446
this is srsue log

```shell
2024-10-14T08:11:39.797868 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=4usec latency_hist=[999, 1, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:40.855333 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=3usec latency_hist=[1000, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:41.925007 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=5usec latency_hist=[1000, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:42.987781 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=6usec latency_hist=[997, 2, 0, 1, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:44.047635 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=4usec latency_hist=[1000, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:45.131254 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=7usec latency_hist=[1000, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:46.207354 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=8usec latency_hist=[990, 9, 1, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:47.266207 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=4usec latency_hist=[998, 2, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:48.322127 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=3usec latency_hist=[1000, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:49.378135 [METRICS ] [I] Cell Scheduler Metrics: error_indications=0 mean_latency=4usec latency_hist=[1000, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2024-10-14T08:11:50.439255 [METRICS ] [I] Cell Scheduler Metrics: error_imingrui

this is gnb log

liumr3 commented 1 month ago

could you send your log files (gnb, srsue and core network)?

this is open5gs amf log,i don't use docker to run open5gs ,i use sudo apt-get install open5gs

10/14 14:39:36.642: [app] INFO: File Logging: '/var/log/open5gs/amf.log' (../lib/app/ogs-init.c:136)
10/14 14:39:36.644: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.200:7777] (../lib/sbi/context.c:474)
10/14 14:39:36.644: [metrics] INFO: metrics_server() [http://10.53.1.2]:9090 (../lib/metrics/prometheus/context.c:299)
10/14 14:39:36.644: [sbi] INFO: NF Service [namf-comm] (../lib/sbi/context.c:1829)
10/14 14:39:36.644: [sbi] INFO: nghttp2_server() [http://10.53.1.2]:38412 (../lib/sbi/nghttp2-server.c:424)
10/14 14:39:36.644: [amf] INFO: ngap_server() [10.53.1.2]:38412 (../src/amf/ngap-sctp.c:61)
10/14 14:39:36.644: [sctp] INFO: AMF initialize...done (../src/amf/app.c:33)
10/14 14:39:36.646: [sbi] INFO: [148c3558-89f7-41ef-8c85-cbee34a40cc8] NF registered [Heartbeat:10s] (../lib/sbi/nf-sm.c:208)
10/14 14:39:36.648: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.648: [sbi] INFO: [148ccba8-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.647420+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:39:36.648: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.648: [sbi] INFO: [148cd38c-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.647585+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:39:36.648: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.648: [sbi] INFO: [148cd8aa-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.647718+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:39:36.648: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.648: [sbi] INFO: [148cdc42-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.647803+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:39:36.649: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.649: [sbi] INFO: [148cde4a-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.647855+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:39:36.649: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.649: [sbi] INFO: [148ce674-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.648063+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:39:36.649: [sbi] INFO: NF EndPoint(addr) setup [127.0.0.10:7777] (../lib/sbi/nnrf-handler.c:949)
10/14 14:39:36.649: [sbi] INFO: [148cee62-89f7-41ef-99f3-4b8c2509ba53] Subscription created until 2024-10-15T14:39:36.648267+08:00 [duration:86400000000,validity:86400.000000,patch:43200.000000] (../lib/sbi/nnrf-handler.c:868)
10/14 14:41:41.102: [amf] INFO: gNB-N2 accepted[10.53.1.1]:37039 in ng-path module (../src/amf/ngap-sctp.c:113)
10/14 14:41:41.103: [amf] INFO: gNB-N2 accepted[10.53.1.1] in master_sm module (../src/amf/amf-sm.c:796)
10/14 14:41:41.106: [amf] INFO: [Added] Number of gNBs is now 1 (../src/amf/context.c:1238)
10/14 14:41:41.106: [amf] INFO: gNB-N2[10.53.1.1] max_num_of_ostreams : 30 (../src/amf/amf-sm.c:842)
10/14 14:43:03.548: [amf] INFO: InitialUEMessage (../src/amf/ngap-handler.c:435)
10/14 14:43:03.548: [amf] INFO: [Added] Number of gNB-UEs is now 1 (../src/amf/context.c:2694)
10/14 14:43:03.548: [amf] INFO:     RAN_UE_NGAP_ID[0] AMF_UE_NGAP_ID[1] TAC[7] CellID[0x66c000] (../src/amf/ngap-handler.c:596)
10/14 14:43:03.548: [amf] INFO: [suci-0-001-01-0000-0-0-0123456780] Unknown UE by SUCI (../src/amf/context.c:1861)
10/14 14:43:03.548: [amf] INFO: [Added] Number of AMF-UEs is now 1 (../src/amf/context.c:1638)
10/14 14:43:03.549: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1220)
10/14 14:43:03.549: [gmm] INFO: [suci-0-001-01-0000-0-0-0123456780]    SUCI (../src/amf/gmm-handler.c:174)
10/14 14:43:03.550: [gmm] ERROR: [suci-0-001-01-0000-0-0-0123456780] HTTP response error [400] (../src/amf/gmm-sm.c:1800)
10/14 14:43:03.550: [amf] WARNING: [suci-0-001-01-0000-0-0-0123456780] Registration reject [95] (../src/amf/nas-path.c:211)
10/14 14:43:03.717: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1726)
10/14 14:43:03.717: [amf] INFO:     RAN_UE_NGAP_ID[0] AMF_UE_NGAP_ID[1] (../src/amf/ngap-handler.c:1727)
10/14 14:43:03.717: [amf] INFO:     SUCI[suci-0-001-01-0000-0-0-0123456780] (../src/amf/ngap-handler.c:1731)
10/14 14:43:03.717: [amf] INFO: [Removed] Number of gNB-UEs is now 0 (../src/amf/context.c:2701)
10/14 14:43:03.717: [amf] INFO: [Removed] Number of AMF-UEs is now 0 (../src/amf/context.c:1735)
pgawlowicz commented 1 month ago

so the core network rejects the UE:

10/14 14:43:03.548: [amf] INFO: [suci-0-001-01-0000-0-0-0123456780] Unknown UE by SUCI (../src/amf/context.c:1861)
...
10/14 14:43:03.550: [gmm] ERROR: [suci-0-001-01-0000-0-0-0123456780] HTTP response error [400] (../src/amf/gmm-sm.c:1800)
10/14 14:43:03.550: [amf] WARNING: [suci-0-001-01-0000-0-0-0123456780] Registration reject [95] (../src/amf/nas-path.c:211)
10/14 14:43:03.717: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1726)

Did you add the UE details to the subscriber database?

liumr3 commented 1 month ago

so the core network rejects the UE:

10/14 14:43:03.548: [amf] INFO: [suci-0-001-01-0000-0-0-0123456780] Unknown UE by SUCI (../src/amf/context.c:1861)
...
10/14 14:43:03.550: [gmm] ERROR: [suci-0-001-01-0000-0-0-0123456780] HTTP response error [400] (../src/amf/gmm-sm.c:1800)
10/14 14:43:03.550: [amf] WARNING: [suci-0-001-01-0000-0-0-0123456780] Registration reject [95] (../src/amf/nas-path.c:211)
10/14 14:43:03.717: [amf] INFO: UE Context Release [Action:3] (../src/amf/ngap-handler.c:1726)

Did you add the UE details to the subscriber database?

I add UE details to the subscriber database:

open5gs> db.subsribers.find()
[
  {
    _id: ObjectId('670ddfaa939dcf943bfe6911'),
    imsi: '001010123456780',
    key: '00112233445566778899aabbccddeeff',
    opc: '63BFA50EE6523365FF14C1F45F88737D',
    sqn: 0,
    pdn: [ { apn: 'srsran', qos: { qci: 9 } } ]
  }
]

nonthing changed

pgawlowicz commented 1 month ago

could you share your config and log files?

liumr3 commented 1 month ago

could you share your config and log files? ue.log gnb.log gnb_zmq.txt ue_zmq.txt amf.txt amf.log

截图 2024-10-15 19-29-45 截图 2024-10-15 19-29-38 截图 2024-10-15 19-29-31 截图 2024-10-15 19-28-57

pgawlowicz commented 1 month ago

Could you try to set Authentication Management Field (AMF) to 8000. Could you assign IPv4 address like here? image

liumr3 commented 1 month ago

Could you try to set Authentication Management Field (AMF) to 8000. Could you assign IPv4 address like here? image i do it as your follows, unfornately, the problems still alive 截图 2024-10-16 10-15-11 amf.log

pgawlowicz commented 1 month ago

There is some issue in communication between amf and gmm:

10/16 09:47:15.081: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1220)
10/16 09:47:15.081: [gmm] INFO: [suci-0-001-01-0000-0-0-0123456780]    SUCI (../src/amf/gmm-handler.c:174)
10/16 09:47:15.083: [gmm] ERROR: [suci-0-001-01-0000-0-0-0123456780] HTTP response error [400] (../src/amf/gmm-sm.c:1800)
10/16 09:47:15.083: [amf] WARNING: [suci-0-001-01-0000-0-0-0123456780] Registration reject [95] (../src/amf/nas-path.c:211)

Could you try with the dockerized open5gs version?

liumr3 commented 1 month ago

There is some issue in communication between amf and gmm:

10/16 09:47:15.081: [gmm] INFO: Registration request (../src/amf/gmm-sm.c:1220)
10/16 09:47:15.081: [gmm] INFO: [suci-0-001-01-0000-0-0-0123456780]    SUCI (../src/amf/gmm-handler.c:174)
10/16 09:47:15.083: [gmm] ERROR: [suci-0-001-01-0000-0-0-0123456780] HTTP response error [400] (../src/amf/gmm-sm.c:1800)
10/16 09:47:15.083: [amf] WARNING: [suci-0-001-01-0000-0-0-0123456780] Registration reject [95] (../src/amf/nas-path.c:211)

Could you try with the dockerized open5gs version?

I found the problem in amf.yaml is

10/18 01:09:05.633: [gmm] ERROR: [suci-0-001-01-0000-0-0-0123456780] HTTP response error [400] (../src/amf/gmm-sm.c:1800)
10/18 01:09:05.633: [amf] WARNING: [suci-0-001-01-0000-0-0-0123456780] Registration reject [95] (../src/amf/nas-path.c:211)

and I check the difference your subscribe and me, I don't know how can you get the IMEISV=012345670000101, it's different from the imei = 353490069873319 in UE_ZMQ.conf, and your SQN=64 i also don't have.