herlesupreeth / docker_open5gs

Docker files to run open5gs + IMS + eNB + gNB + NR-UE in a docker
BSD 2-Clause "Simplified" License
279 stars 156 forks source link

ogs_gtp_xact_update_tx() failed #326

Open srinidhikrs opened 1 month ago

srinidhikrs commented 1 month ago

We have a Volte testbed with srsenb (USRP_B210) + open5gs + kamailio IMS + IMS Application server. We are testing Video Ringbacktone service using our IMS application server. When B-party is ringing , IMS applicaion server upgrades audio session to video session between A-party and Video Tone service . At the same instance mmed is aborting with the following trace :

05/29 05:18:35.732: [esm] DEBUG: Modify EPS bearer context accept (../src/mme/esm-sm.c:331) 05/29 05:18:35.732: [esm] DEBUG: IMSI[001010123456793] PTI[0] EBI[7] (../src/mme/esm-sm.c:332) 05/29 05:18:35.732: [mme] DEBUG: Update Bearer Response (../src/mme/mme-s11-build.c:660) 05/29 05:18:35.732: [mme] DEBUG: MME_S11_TEID[1011] SGW_S11_TEID[201] (../src/mme/mme-s11-build.c:661) 05/29 05:18:35.732: [core] TRACE: BUILD L#0 [Cause] T:2 L:0 I:0 (cls:9 vsz:24) off:0x7f9aa17f5c40 (../lib/core/ogs-tlv-msg.c:386) 05/29 05:18:35.732: [core] TRACE: BUILD C#1 [Bearer Context] T:93 I:0 (vsz=616) off:0x7f9aa17f5c58 (../lib/core/ogs-tlv-msg.c:364) 05/29 05:18:35.732: [core] TRACE: BUILD L#0 [EBI] T:73 L:1 I:0 (cls:0 vsz:16) off:0x7f9aa17f5c60 (../lib/core/ogs-tlv-msg.c:386) 05/29 05:18:35.732: [core] TRACE: BUILD L#11 [Cause] T:2 L:0 I:0 (cls:9 vsz:24) off:0x7f9aa17f5d60 (../lib/core/ogs-tlv-msg.c:386) 05/29 05:18:35.732: [core] TRACE: BUILD L#9 [UE Time Zone] T:114 L:0 I:0 (cls:9 vsz:24) off:0x7f9aa17f5f60 (../lib/core/ogs-tlv-msg.c:386) 05/29 05:18:35.732: [core] TRACE: BUILD L#10 [ULI] T:86 L:0 I:0 (cls:9 vsz:24) off:0x7f9aa17f5f78 (../lib/core/ogs-tlv-msg.c:386) 05/29 05:18:35.732: [gtp] DEBUG: [10] REMOTE UPD TX-98 peer [127.0.0.3]:2123 (../lib/gtp/xact.c:348) 05/29 05:18:35.732: [gtp] ERROR: invalid step[2] (../lib/gtp/xact.c:393) 05/29 05:18:35.732: [mme] ERROR: ogs_gtp_xact_update_tx() failed (../src/mme/mme-gtp-path.c:460) 05/29 05:18:35.732: [esm] FATAL: esm_state_active: Assertion `OGS_OK == mme_gtp_send_update_bearer_response( bearer, OGS_GTP2_CAUSE_REQUEST_ACCEPTED)' failed. (../src/mme/esm-sm.c:335) 05/29 05:18:35.732: [core] FATAL: backtrace() returned 9 addresses (../lib/core/ogs-abort.c:37) ./open5gs-mmed(+0x74746) [0x55bd04fe5746] /root/open5gs/install/lib/x86_64-linux-gnu/libogscore.so.2(ogs_fsm_dispatch+0x119) [0x7f9b205d8bc6] ./open5gs-mmed(+0x8b4f0) [0x55bd04ffc4f0] /root/open5gs/install/lib/x86_64-linux-gnu/libogscore.so.2(ogs_fsm_dispatch+0x119) [0x7f9b205d8bc6] ./open5gs-mmed(+0x9e99) [0x55bd04f7ae99] /root/open5gs/install/lib/x86_64-linux-gnu/libogscore.so.2(+0x11934) [0x7f9b205c9934] /lib/x86_64-linux-gnu/libc.so.6(+0x94ac3) [0x7f9b1fecaac3] /lib/x86_64-linux-gnu/libc.so.6(+0x126850) [0x7f9b1ff5c850]

Please help us to fix this issue.

volte_testcall1.zip open5gs_logs.zip

Thanks Srinidhi

herlesupreeth commented 1 month ago

Hey @srinidhikrs I havent worked that much with Application Server involved. I will try to look over the pcap tomorrow.

srinidhikrs commented 1 month ago

Hi ,

Thanks for the response.

I had also raised this issue in open5gs forum.

Sukchan has identified a bug in open5gs-mmed.

https://github.com/open5gs/open5gs/issues/3240

So waiting for Sukchan to provide the fix so that I can continue testing.

Thanks Srinidhi

srinidhikrs commented 1 month ago

Hi ,

I have updated the sip flow in IMS Application server to avoid second bearer update before first update response is executed .

Now the mmed is not aborting.

But the media packets from IMS MRF is not reaching the UE.

The service call flow is as follows :

1)A-party makes call to B-party

2)B-party phone starts ringing

3)IMS Application server(172.19.118.233) connects media (audio+video) between A-party and IMS MRF (172.19.118.233) using SIP Update request

4)IMS MRF starts playing media (audio+video) to A-party .

Observations when A-party is connected with IMS MRF server for media:

1)In the captured pcap file , GTP (Error Indication) packets are seen

2)In smf.log the following error is observed around same time 06/01 05:07:37.010: [smf] ERROR: [001010123456793:ims] Error Indication from SGW-C (../src/smf/n4-handler.c:1366)

3)In sgwc.log , the following error is seen 06/01 05:07:36.961: [sgwc] ERROR: [001010123456793] Error Indication(Dedicated Bearer) from SMF (../src/sgwc/sxa-handler.c:1501)

4)In sgwu.log , the following error is seen 06/01 05:07:36.960: [sgwu] ERROR: [127.0.0.6] Send Error Indication [TEID:0xc44e] to [127.0.1.1] (../src/sgwu/gtp-path.c:212)

5)IN upf.log , the following error is seen 06/01 05:07:36.952: [upf] ERROR: [127.0.0.7] Send Error Indication [TEID:0xb36a] to [127.0.0.6] (../src/upf/gtp-path.c:474)

6)In enb.log , the following errors are seen :

2024-06-01T05:06:41.601201 [PDCP ] [W] Setting discard timer to 1500ms, to avoid issues with lingering SDUs in the Unacknowledged SDUs map. LCID=4 2024-06-01T05:07:35.409730 [RRC ] [E] Expected RRCReconfigurationComplete with transaction ID: 0, got 1 2024-06-01T05:07:35.431703 [RRC ] [E] Expected RRCReconfigurationComplete with transaction ID: 0, got 1 2024-06-01T05:07:36.811721 [RRC ] [E] Expected RRCReconfigurationComplete with transaction ID: 0, got 1 2024-06-01T05:07:36.960647 [GTPU ] [E] gtpu_read_header - Unhandled GTP-U Extension Header Type: 0x40 2024-06-01T05:07:36.976486 [GTPU ] [E] gtpu_read_header - Unhandled GTP-U Extension Header Type: 0x40 2024-06-01T05:07:36.984053 [GTPU ] [E] gtpu_read_header - Unhandled GTP-U Extension Header Type: 0x40 2024-06-01T05:07:37.011184 [GTPU ] [E] gtpu_read_header - Unhandled GTP-U Extension Header Type: 0x40

Please help in identifying and fixing the media issue from IMS-MRF (172.19.118.233) to A-party

Thanks Srinidhi

conf.zip open5gs_logs.zip volte_test_call_pcap.zip enb.zip

herlesupreeth commented 1 month ago

But the media packets from IMS MRF is not reaching the UE.

Cant confirm completely since your ESP packets are encrypted, but I think the ports in the packet filters maybe wrong.

Can you re-try the above scenario by adding the following kamailio_pcscf.cfg and re-attach + re-take the pcap?

modparam("ims_ipsec_pcscf", "ipsec_preferred_ealg", "null")

srinidhikrs commented 4 weeks ago

Hi,

With the following config : modparam("ims_ipsec_pcscf", "ipsec_preferred_ealg", "null")

The pcscf did not come up with error : ipsec_preferred_ealg is invalid

I updated open5gs to the latest main branch to include the latest patch (https://github.com/open5gs/open5gs/issues/3240) and made a test call. But now smf is aborting : 06/04 04:46:08.977: [core] TRACE: PARSE L#3 [ULI] T:86 L:0 I:0 (cls:9 vsz:24) off:0x7f432d7f8208 (../lib/core/ogs-tlv-msg.c:721) 06/04 04:46:08.977: [gtp] DEBUG: [3] LOCAL Find GTPv2 peer [127.0.0.3]:2123 (../lib/gtp/xact.c:963) 06/04 04:46:08.977: [gtp] DEBUG: [3] LOCAL Receive peer [127.0.0.3]:2123 (../lib/gtp/xact.c:980) 06/04 04:46:08.977: [gtp] DEBUG: [3] LOCAL UPD RX-98 peer [127.0.0.3]:2123 (../lib/gtp/xact.c:448) 06/04 04:46:08.977: [smf] FATAL: smf_s5c_handle_update_bearer_response: Assertion `sess' failed. (../src/smf/s5c-handler.c:853) 06/04 04:46:08.977: [core] FATAL: backtrace() returned 8 addresses (../lib/core/ogs-abort.c:37) ./open5gs-smfd(+0x4a413) [0x55cdb845f413] ./open5gs-smfd(+0x24e79) [0x55cdb8439e79] /root/open5gs/install/lib/x86_64-linux-gnu/libogscore.so.2(ogs_fsm_dispatch+0x119) [0x7f43b8ce2c6e] ./open5gs-smfd(+0x10418) [0x55cdb8425418] /root/open5gs/install/lib/x86_64-linux-gnu/libogscore.so.2(+0x119dc) [0x7f43b8cd39dc] /lib/x86_64-linux-gnu/libc.so.6(+0x94ac3) [0x7f43b7be6ac3] /lib/x86_64-linux-gnu/libc.so.6(+0x126850) [0x7f43b7c78850]

Still there is no media between A-party and IMS MRF.

Please help in resolving the smf abort issues and also the media issue

In enb.log observing the following error:

2024-06-04T04:46:08.812902 [RRC ] [D] Content: [ { "UL-DCCH-Message": { "message": { "c1": { "rrcConnectionReconfigurationComplete": { "rrc-TransactionIdentifier": 1, "criticalExtensions": { "rrcConnectionReconfigurationComplete-r8": { } } } } } } } ] 2024-06-04T04:46:08.812905 [MAC ] [D] [ 2991] SCHED: Allocated PRACH RBs mask=0fc0000000000000000000000 for tti_tx_ul=3001 2024-06-04T04:46:08.812906 [RRC ] [E] Expected RRCReconfigurationComplete with transaction ID: 0, got 1

Thanks Srinidhi

volte_testlogs.zip

herlesupreeth commented 4 weeks ago

modparam("ims_ipsec_pcscf", "ipsec_preferred_ealg", "null")

The pcscf did not come up with error : ipsec_preferred_ealg is invalid

Then, you are not using the latest commits from this repo (which uses latest kamailio code)