UP initiated association setup

pirog-spb commented 1 year ago

According to TS 129 244:

6.2.6.3 PFCP Association Setup Initiated by the UP Function
~~6.2.7.3 PFCP Association Update Procedure Initiated by UP Function (see Graceful Release)~~
~~6.2.8 PFCP Association Release Procedure~~

kade-ddnkv commented 9 months ago

Association Setup Procedure free5gc: "incomplete" support open5gs: supports

Association Update Procedure free5gc: doesn't support open5gs: doesn't support

Association Release Procedure free5gc: supports in its own way, no specification open5gs: doesn't support

It turns out that the feature release is meaningless

kade-ddnkv commented 9 months ago

The current goal: implement UP initiated Assotiation Setup Request. A detailed description of the progress on this issue can be found in its pull request: https://github.com/edgecomllc/eupf/pull/497

kade-ddnkv commented 8 months ago

Current status:

Faced some problems while setting up associations in open5gs kubernetes environment.

Problem №1 All interactions in open5gs kubernetes are meant to happens through services (because pods can restart and change their IPs). In that case, two associations are established: one initiated from SMF and one initiated from UPF. These associations are treated as different because in both SMF and UPF the primary key to an association is the address, from which request/responce was received. So, UPF establishes association with SMF service, and SMF establishes association with UPF service. Both of them are working.

Problem №2 We can change a primary key to PFCP association from address to Node ID (a field in PFCP Association Setup Request/Response), as it was said in 3GPP specification. However, in such case two subproblem appear:

2.1. Heartbeats. When we get Heartbeat Request, how can we find specific association to that Heartbeat?

2.2. How can UPF understand when it should stop sending Requests? In config we set a service alias to connect to. But when UPF gets Response from SMF, there will be a Node ID of a SMF itself. For example, service name is "open5gs-smf-pfcp", and Node ID is some "10.244.1.24". So the question is: How can UPF know if it should sending Requests to a service?

PapaySail commented 8 months ago

✔ Solution for setting up associations in open5gs kubernetes environment.

To set open5gs-smf-pfcp service as Headless `spec.clusterIP: None`

manifest for headless service

```yaml apiVersion: v1 kind: Service metadata: name: open5gs-smf-pfcp namespace: open5gs20893 labels: app.kubernetes.io/instance: open5gs-smf app.kubernetes.io/managed-by: Helm app.kubernetes.io/name: open5gs-smf helm.sh/chart: open5gs-smf-2.0.10 k8slens-edit-resource-version: v1 annotations: meta.helm.sh/release-name: open5gs-smf meta.helm.sh/release-namespace: open5gs20893 spec: ports: - name: pfcp protocol: UDP port: 8805 targetPort: pfcp selector: app.kubernetes.io/instance: open5gs-smf app.kubernetes.io/name: open5gs-smf clusterIP: None type: ClusterIP sessionAffinity: None publishNotReadyAddresses: true ipFamilies: - IPv4 ipFamilyPolicy: SingleStack internalTrafficPolicy: Cluster ``` `kubectl apply -f `

OK. Deployed with success. Fully testetd with 0-scenario.

Logs. SMF was started before UPF

SMF log: ```ruby Open5GS daemon v2.4.11 12/15 17:09:21.325: [app] INFO: Configuration: '/opt/open5gs/etc/open5gs/smf.yaml' (../lib/app/ogs-init.c:126) 12/15 17:09:26.359: [metrics] INFO: Prometheus mhd_server() [0.0.0.0]:9090 (../lib/metrics/prometheus/context.c:320) 12/15 17:09:26.359: [smf] WARNING: No diameter configuration (../src/smf/fd-path.c:30) 12/15 17:09:26.359: [gtp] INFO: gtp_server() [10.233.78.77]:2123 (../lib/gtp/path.c:30) 12/15 17:09:26.360: [gtp] INFO: gtp_server() [10.233.78.77]:2152 (../lib/gtp/path.c:30) 12/15 17:09:26.360: [pfcp] INFO: pfcp_server() [10.233.78.77]:8805 (../lib/pfcp/path.c:30) 12/15 17:09:26.360: [pfcp] INFO: ogs_pfcp_connect() [10.233.0.179]:8805 (../lib/pfcp/path.c:61) 12/15 17:09:26.362: [sbi] INFO: NF Service [nsmf-pdusession] (../lib/sbi/context.c:1400) 12/15 17:09:26.362: [sbi] INFO: nghttp2_server() [10.233.78.77]:7777 (../lib/sbi/nghttp2-server.c:150) 12/15 17:09:26.362: [app] INFO: SMF initialize...done (../src/smf/app.c:31) 12/15 17:09:26.366: [sbi] INFO: [b0683b90-9b6c-41ee-ac84-ddbe8dcb3e85] NF registered [Heartbeat:10s] (../lib/sbi/nf-sm.c:222) 12/15 17:09:33.866: [pfcp] WARNING: [1] LOCAL No Reponse. Give up! for step 1 type 5 peer [10.233.0.179]:8805 (../lib/pfcp/xact.c:613) 12/15 17:09:37.361: [smf] WARNING: Retry to association with peer [10.233.0.179]:8805 failed (../src/smf/pfcp-sm.c:107) 12/15 17:09:44.868: [pfcp] WARNING: [2] LOCAL No Reponse. Give up! for step 1 type 5 peer [10.233.0.179]:8805 (../lib/pfcp/xact.c:613) 12/15 17:09:48.364: [smf] WARNING: Retry to association with peer [10.233.0.179]:8805 failed (../src/smf/pfcp-sm.c:107) 12/15 17:09:55.869: [pfcp] WARNING: [3] LOCAL No Reponse. Give up! for step 1 type 5 peer [10.233.0.179]:8805 (../lib/pfcp/xact.c:613) 12/15 17:09:59.368: [smf] WARNING: Retry to association with peer [10.233.0.179]:8805 failed (../src/smf/pfcp-sm.c:107) 12/15 17:10:06.872: [pfcp] WARNING: [4] LOCAL No Reponse. Give up! for step 1 type 5 peer [10.233.0.179]:8805 (../lib/pfcp/xact.c:613) 12/15 17:10:10.372: [smf] WARNING: Retry to association with peer [10.233.0.179]:8805 failed (../src/smf/pfcp-sm.c:107) 12/15 17:10:13.386: [pfcp] INFO: ogs_pfcp_connect() [10.233.64.11]:8805 (../lib/pfcp/path.c:61) 12/15 17:10:13.386: [pfcp] WARNING: F-TEID allocation/release not supported with peer [10.233.64.11]:8805 (../lib/pfcp/handler.c:90) 12/15 17:10:13.386: [smf] INFO: PFCP associated [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:174) 12/15 17:10:17.875: [pfcp] WARNING: [5] LOCAL No Reponse. Give up! for step 1 type 5 peer [10.233.0.179]:8805 (../lib/pfcp/xact.c:613) 12/15 17:10:18.385: [smf] WARNING: PFCP[REQ] has already been associated [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:217) 12/15 17:10:18.385: [pfcp] WARNING: F-TEID allocation/release not supported with peer [10.233.64.11]:8805 (../lib/pfcp/handler.c:90) 12/15 17:10:21.373: [smf] WARNING: Retry to association with peer [10.233.0.179]:8805 failed (../src/smf/pfcp-sm.c:107) 12/15 17:10:21.373: [pfcp] WARNING: F-TEID allocation/release not supported with peer [10.233.0.179]:8805 (../lib/pfcp/handler.c:138) 12/15 17:10:21.373: [smf] INFO: PFCP associated [10.233.0.179]:8805 (../src/smf/pfcp-sm.c:174) 12/15 17:10:24.393: [pfcp] ERROR: invalid step[0] type[2] (../lib/pfcp/xact.c:432) 12/15 17:10:24.393: [pfcp] ERROR: ogs_pfcp_xact_update_rx() failed (../lib/pfcp/xact.c:708) 12/15 17:10:26.894: [pfcp] ERROR: invalid step[0] type[2] (../lib/pfcp/xact.c:432) 12/15 17:10:26.894: [pfcp] ERROR: ogs_pfcp_xact_update_rx() failed (../lib/pfcp/xact.c:708) 12/15 17:10:28.385: [pfcp] WARNING: [2] REMOTE Request Duplicated. Retransmit! for step 2 type 1 peer [10.233.0.179]:8805 (../lib/pfcp/xact.c:390) 12/15 17:10:29.400: [pfcp] ERROR: invalid step[0] type[2] (../lib/pfcp/xact.c:432) 12/15 17:10:29.400: [pfcp] ERROR: ogs_pfcp_xact_update_rx() failed (../lib/pfcp/xact.c:708) 12/15 17:10:31.897: [pfcp] WARNING: [7] LOCAL No Reponse. Give up! for step 1 type 1 peer [10.233.64.11]:8805 (../lib/pfcp/xact.c:613) 12/15 17:10:31.897: [smf] WARNING: No Heartbeat from UPF [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:316) 12/15 17:10:31.897: [smf] INFO: PFCP de-associated [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:181) 12/15 17:18:42.266: [smf] INFO: [Added] Number of SMF-UEs is now 1 (../src/smf/context.c:898) 12/15 17:18:42.266: [smf] INFO: [Added] Number of SMF-Sessions is now 1 (../src/smf/context.c:2975) 12/15 17:18:42.267: [sbi] WARNING: Try to discover [nudm-sdm] (../lib/sbi/path.c:114) 12/15 17:18:42.269: [sbi] INFO: [4585b4da-9a1b-41ee-9b79-a3c44544f50c] (NF-discover) NF registered (../lib/sbi/nnrf-handler.c:731) 12/15 17:18:42.269: [sbi] INFO: [4585b4da-9a1b-41ee-9b79-a3c44544f50c] (NF-discover) NF Profile updated (../lib/sbi/nnrf-handler.c:758) 12/15 17:18:42.275: [sbi] WARNING: Try to discover [npcf-smpolicycontrol] (../lib/sbi/path.c:114) 12/15 17:18:42.276: [sbi] INFO: [6e09fbb4-9a1b-41ee-9855-d5511278fe52] (NF-discover) NF registered (../lib/sbi/nnrf-handler.c:731) 12/15 17:18:42.277: [sbi] INFO: [6e09fbb4-9a1b-41ee-9855-d5511278fe52] (NF-discover) NF Profile updated (../lib/sbi/nnrf-handler.c:758) 12/15 17:18:42.290: [smf] INFO: UE SUPI[imsi-208930000000001] DNN[internet] IPv4[10.11.0.2] IPv6[] (../src/smf/npcf-handler.c:495) 12/15 17:18:42.292: [gtp] INFO: gtp_connect() [10.233.0.179]:2152 (../lib/gtp/path.c:60) 12/15 17:18:42.294: [sbi] WARNING: Try to discover [namf-comm] (../lib/sbi/path.c:114) 12/15 17:18:42.295: [sbi] INFO: [546c9572-9a1b-41ee-8cdb-ddf4c340f98c] (NF-discover) NF registered (../lib/sbi/nnrf-handler.c:731) 12/15 17:18:42.295: [sbi] INFO: [546c9572-9a1b-41ee-8cdb-ddf4c340f98c] (NF-discover) NF Profile updated (../lib/sbi/nnrf-handler.c:758) Stream closed EOF for open5gs20893/open5gs-smf-76dd6bd497-d7bm9 (open5gs-smf) ``` eUPF start log: ```ruby [GIN-debug] [WARNING] Running in "debug" mode. Switch to "release" mode in production. - using env: export GIN_MODE=release - using code: gin.SetMode(gin.ReleaseMode) [GIN-debug] GET /api/v1/health --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).InitRoutes.func1 (4 handlers) [GIN-debug] GET /api/v1/upf_pipeline --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listUpfPipeline-fm (4 handlers) [GIN-debug] GET /api/v1/xdp_stats --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).displayXdpStatistics-fm (4 handlers) [GIN-debug] GET /api/v1/packet_stats --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).displayPacketStats-fm (4 handlers) [GIN-debug] GET /api/v1/config --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).displayConfig-fm (4 handlers) [GIN-debug] POST /api/v1/config --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).editConfig-fm (4 handlers) [GIN-debug] GET /api/v1/uplink_pdr_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).getUplinkPdrValue-fm (4 handlers) [GIN-debug] PUT /api/v1/uplink_pdr_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).setUplinkPdrValue-fm (4 handlers) [GIN-debug] GET /api/v1/qer_map --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listQerMapContent-fm (4 handlers) [GIN-debug] GET /api/v1/qer_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).getQerValue-fm (4 handlers) [GIN-debug] PUT /api/v1/qer_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).setQerValue-fm (4 handlers) [GIN-debug] GET /api/v1/far_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).getFarValue-fm (4 handlers) [GIN-debug] PUT /api/v1/far_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).setFarValue-fm (4 handlers) [GIN-debug] GET /api/v1/pfcp_associations --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listPfcpAssociations-fm (4 handlers) [GIN-debug] GET /api/v1/pfcp_associations/full --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listPfcpAssociationsFull-fm (4 handlers) [GIN-debug] GET /api/v1/pfcp_sessions --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listPfcpSessionsFiltered-fm (4 handlers) [GIN-debug] GET /swagger/*any --> github.com/swaggo/gin-swagger.CustomWrapHandler.func1 (4 handlers) [GIN-debug] [WARNING] Creating an Engine instance with the Logger and Recovery middleware already attached. [GIN-debug] [WARNING] Running in "debug" mode. Switch to "release" mode in production. - using env: export GIN_MODE=release - using code: gin.SetMode(gin.ReleaseMode) [GIN-debug] GET /metrics --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).InitMetricsRoute.func1.1 (4 handlers) 2023/12/15 17:10:08 INF running on :8080 2023/12/15 17:10:08 INF running on :9090 2023/12/15 17:10:13 DBG Sequence ID: 1 2023/12/15 17:10:13 INF Sent Association Setup Request to: open5gs-smf-pfcp 2023/12/15 17:10:13 DBG Received 35 bytes from 10.233.78.77:8805 2023/12/15 17:10:13 DBG Handling PFCP message from 10.233.78.77:8805 2023/12/15 17:10:13 INF Got Association Setup Response from: 10.233.78.77 2023/12/15 17:10:13 INF Got Association Setup Response with CPFunctionFeatures from: 10.233.78.77. CPFunctionFeatures: 0 2023/12/15 17:10:13 INF Saving new association: &{ID:10.233.78.77 Addr:10.233.78.77 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatRetries:0 cancelRetries:} 2023/12/15 17:10:18 DBG Sequence ID: 2 2023/12/15 17:10:18 INF Sent Association Setup Request to: open5gs-smf-pfcp 2023/12/15 17:10:18 DBG Stop sending Association Setup Request to open5gs-smf-pfcp 2023/12/15 17:10:18 DBG Received 35 bytes from 10.233.78.77:8805 2023/12/15 17:10:18 DBG Handling PFCP message from 10.233.78.77:8805 2023/12/15 17:10:18 INF Got Association Setup Response from: 10.233.78.77 2023/12/15 17:10:18 INF Got Association Setup Response with CPFunctionFeatures from: 10.233.78.77. CPFunctionFeatures: 0 2023/12/15 17:10:18 WRN Association with NodeID: 10.233.78.77 and address: 10.233.78.77 already exists 2023/12/15 17:10:18 WRN Session retention is not yet implemented 2023/12/15 17:10:18 INF Saving new association: &{ID:10.233.78.77 Addr:10.233.78.77 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatRetries:0 cancelRetries:} 2023/12/15 17:10:21 DBG Received 30 bytes from 10.233.78.77:31129 2023/12/15 17:10:21 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:21 INF Got Association Setup Request from: 10.233.78.77 2023/12/15 17:10:21 INF Association Setup Request: Node ID: 10.233.78.77 Recovery Time: 2023-12-15 17:09:21 +0000 UTC 2023/12/15 17:10:21 WRN Association with NodeID: 10.233.78.77 and address: 10.233.78.77 already exists 2023/12/15 17:10:21 WRN Session retention is not yet implemented 2023/12/15 17:10:21 INF Saving new association: &{ID:10.233.78.77 Addr:10.233.78.77 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatRetries:0 cancelRetries:} 2023/12/15 17:10:23 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:10:23 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:23 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:23 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:24 DBG Received 16 bytes from 10.233.78.77:8805 2023/12/15 17:10:24 DBG Handling PFCP message from 10.233.78.77:8805 2023/12/15 17:10:24 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:24 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:10:26 DBG Received 16 bytes from 10.233.78.77:8805 2023/12/15 17:10:26 DBG Handling PFCP message from 10.233.78.77:8805 2023/12/15 17:10:26 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:26 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:10:28 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:10:28 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:28 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:28 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:29 DBG Received 16 bytes from 10.233.78.77:8805 2023/12/15 17:10:29 DBG Handling PFCP message from 10.233.78.77:8805 2023/12/15 17:10:29 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:29 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:10:32 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:32 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:32 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:32 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:10:33 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:10:33 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:33 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:33 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:38 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:10:38 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:38 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:38 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:43 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:43 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:43 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:10:43 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:10:43 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:10:43 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:10:43 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:10:43 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 Stream closed EOF for open5gs20893/eupf-cf968d66c-fwcdv (eupf) ``` eUFP log when UE is connected ```ruby Network Instance: internet CreateFAR ID: 3 Apply Action: [2 0] Forwarding Parameters: Network Instance: internet Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:1 IPv4Address:10.233.78.77 IPv6Address: PortNumber:0 CTag:0 STag:0} CreateQER ID: 1 Gate Status DL: 0 Gate Status UL: 0 Max Bitrate DL: 999999 Max Bitrate UL: 999999 QFI: 1 CreateURR ID: 1 Measurement Method: 2 Volume Threshold: &{Flags:1 TotalVolume:104857600 UplinkVolume:0 DownlinkVolume:0} CreateBAR ID: 1 2023/12/15 17:18:42 INF Saving FAR info to session: 1, {Action:12 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:42 DBG EBPF: Put FAR: internalId=0, qerInfo={Action:12 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:42 INF WARN: No OuterHeaderCreation 2023/12/15 17:18:42 INF Saving FAR info to session: 2, {Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:42 DBG EBPF: Put FAR: internalId=1, qerInfo={Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:42 INF Saving FAR info to session: 3, {Action:2 OuterHeaderCreation:1 Teid:1 RemoteIP:1297017098 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:42 DBG EBPF: Put FAR: internalId=2, qerInfo={Action:2 OuterHeaderCreation:1 Teid:1 RemoteIP:1297017098 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:42 INF Saving QER info to session: 1, {GateStatusUL:0 GateStatusDL:0 Qfi:1 MaxBitrateUL:999999000 MaxBitrateDL:999999000 StartUL:0 StartDL:0} 2023/12/15 17:18:42 DBG EBPF: Put QER: internalId=0, qerInfo={GateStatusUL:0 GateStatusDL:0 Qfi:1 MaxBitrateUL:999999000 MaxBitrateDL:999999000 StartUL:0 StartDL:0} 2023/12/15 17:18:42 DBG EBPF: Put PDR Downlink: ipv4=10.11.0.2, pdrInfo={OuterHeaderRemoval:0 FarId:0 QerId:0 SdfFilter:} 2023/12/15 17:18:42 DBG EBPF: Put PDR Uplink: teid=2, pdrInfo={OuterHeaderRemoval:0 FarId:1 QerId:0 SdfFilter:} 2023/12/15 17:18:42 DBG EBPF: Put PDR Uplink: teid=3, pdrInfo={OuterHeaderRemoval:0 FarId:0 QerId:0 SdfFilter:} 2023/12/15 17:18:42 DBG Error extracting PDR info: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to ([\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$ 2023/12/15 17:18:42 INF Session Establishment Request from 10.233.78.77 accepted. 2023/12/15 17:18:42 DBG Received 70 bytes from 10.233.78.77:31129 2023/12/15 17:18:42 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:42 INF Got Session Modification Request from: 10.233.78.77. 2023/12/15 17:18:42 INF Finding association for 10.233.78.77 2023/12/15 17:18:42 INF Finding session 2 2023/12/15 17:18:42 INF Session Modification Request: UpdateFAR ID: 1 Apply Action: [2 0] Update forwarding Parameters: Network Instance: internet Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:1 IPv4Address:10.233.78.101 IPv6Address: PortNumber:0 CTag:0 STag:0} 2023/12/15 17:18:42 INF Updating FAR info: 1, {FarInfo:{Action:2 OuterHeaderCreation:1 Teid:1 RemoteIP:1699670282 LocalIP:188803338 TransportLevelMarking:0} GlobalId:0} 2023/12/15 17:18:42 DBG EBPF: Update FAR: internalId=0, farInfo={Action:2 OuterHeaderCreation:1 Teid:1 RemoteIP:1699670282 LocalIP:188803338 TransportLevelMarking:0} 2023/12/15 17:18:43 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:18:43 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:18:43 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:43 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:18:47 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:18:47 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:47 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:18:47 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:18:48 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:18:48 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:18:48 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:48 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:18:53 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:18:53 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:18:53 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:53 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:18:58 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:18:58 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:18:58 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:58 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:18:58 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:18:58 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:18:58 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:18:58 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:19:03 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:19:03 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:03 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:03 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:19:08 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:19:08 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:08 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:08 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:19:09 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:09 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:09 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:19:09 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:19:13 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:19:13 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:13 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:13 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:19:18 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:19:18 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:18 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:18 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:19:20 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:20 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:20 DBG Got Heartbeat Request with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 2023/12/15 17:19:20 DBG Sent Heartbeat Response to: 10.233.78.77 2023/12/15 17:19:23 DBG Sent Heartbeat Request to: 10.233.78.77 2023/12/15 17:19:23 DBG Received 16 bytes from 10.233.78.77:31129 2023/12/15 17:19:23 DBG Handling PFCP message from 10.233.78.77:31129 2023/12/15 17:19:23 DBG Got Heartbeat Response with TS: 2023-12-15 17:09:21 +0000 UTC, from: 10.233.78.77 Stream closed EOF for open5gs20893/eupf-cf968d66c-fwcdv (eupf) ```

kade-ddnkv commented 8 months ago

Good solution! UPF actually saves only one association. But I suspect that SMF is storing two of them (with eUPF service and eUPF pod). An evidence: After the association initiated by UPF was established:

2023/12/15 17:10:18 INF Got Association Setup Response with CPFunctionFeatures from: 10.233.78.77. CPFunctionFeatures: 0

UPF receives an additional request from SMF (a later timestamp):

2023/12/15 17:10:21 INF Got Association Setup Request from: 10.233.78.77

kade-ddnkv commented 8 months ago

Both SMF and UPF services set to `ClusterIP: None` mode.

In such case UPF doesn't receive an Association Setup Request from SMF. Only Response.

Logs (sorry for the encoding problems)

SMF logs: ``` Open5GS daemon v2.4.11 [32m12/19 01:04:20.333[0m: [[33mapp[0m] [1;32mINFO[0m: Configuration: '/opt/open5gs/etc/open5gs/smf.yaml' (../lib/app/ogs-init.c:126) [32m12/19 01:04:20.380[0m: [[33mmetrics[0m] [1;32mINFO[0m: Prometheus mhd_server() [0.0.0.0]:9090 (../lib/metrics/prometheus/context.c:320) [32m12/19 01:04:20.381[0m: [[33msmf[0m] [1;36mWARNING[0m: No diameter configuration (../src/smf/fd-path.c:30) [32m12/19 01:04:20.381[0m: [[33mgtp[0m] [1;32mINFO[0m: gtp_server() [10.233.78.76]:2123 (../lib/gtp/path.c:30) [32m12/19 01:04:20.381[0m: [[33mgtp[0m] [1;32mINFO[0m: gtp_server() [10.233.78.76]:2152 (../lib/gtp/path.c:30) [32m12/19 01:04:20.381[0m: [[33mpfcp[0m] [1;32mINFO[0m: pfcp_server() [10.233.78.76]:8805 (../lib/pfcp/path.c:30) [32m12/19 01:04:20.381[0m: [[33mpfcp[0m] [1;32mINFO[0m: ogs_pfcp_connect() [10.233.64.11]:8805 (../lib/pfcp/path.c:61) [32m12/19 01:04:20.381[0m: [[33msbi[0m] [1;32mINFO[0m: NF Service [nsmf-pdusession] (../lib/sbi/context.c:1400) [32m12/19 01:04:20.395[0m: [[33msbi[0m] [1;32mINFO[0m: nghttp2_server() [10.233.78.76]:7777 (../lib/sbi/nghttp2-server.c:150) [32m12/19 01:04:20.396[0m: [[33mapp[0m] [1;32mINFO[0m: SMF initialize...done (../src/smf/app.c:31) [32m12/19 01:04:20.398[0m: [[33mpfcp[0m] [1;36mWARNING[0m: F-TEID allocation/release not supported with peer [10.233.64.11]:8805 (../lib/pfcp/handler.c:138) [32m12/19 01:04:20.398[0m: [[33msmf[0m] [1;32mINFO[0m: PFCP associated [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:174) [32m12/19 01:04:20.408[0m: [[33msbi[0m] [1;32mINFO[0m: [8a631b22-9e0a-41ee-801e-bd1640e353b4] NF registered [Heartbeat:10s] (../lib/sbi/nf-sm.c:222) [32m12/19 01:04:40.589[0m: [[33msmf[0m] [1;36mWARNING[0m: PFCP[REQ] has already been associated [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:217) [32m12/19 01:04:40.589[0m: [[33mpfcp[0m] [1;36mWARNING[0m: F-TEID allocation/release not supported with peer [10.233.64.11]:8805 (../lib/pfcp/handler.c:90) [32m12/19 01:04:45.587[0m: [[33msmf[0m] [1;36mWARNING[0m: PFCP[REQ] has already been associated [10.233.64.11]:8805 (../src/smf/pfcp-sm.c:217) [32m12/19 01:04:45.587[0m: [[33mpfcp[0m] [1;36mWARNING[0m: F-TEID allocation/release not supported with peer [10.233.64.11]:8805 (../lib/pfcp/handler.c:90) [32m12/19 01:04:50.588[0m: [[33mpfcp[0m] [1;33mERROR[0m: invalid step[2] type[1] (../lib/pfcp/xact.c:417) [32m12/19 01:04:50.588[0m: [[33mpfcp[0m] [1;33mERROR[0m: ogs_pfcp_xact_update_rx() failed (../lib/pfcp/xact.c:708) ``` eUPF logs: ``` 2023/12/19 01:04:34 Get raw config: map[api_address::8080 association_setup_timeout:5 echo_interval:10 far_map_size:1024 gtp_peer:[] heartbeat_interval:5 heartbeat_retries:3 heartbeat_timeout:5 interface_name:eth0 logging_level:debug metrics_address::9090 n3_address:10.233.64.11 pdr_map_size:1024 pfcp_address::8805 pfcp_node:[open5gs-smf-pfcp] pfcp_node_id:10.233.64.11 qer_map_size:1024 resize_ebpf_maps:false xdp_attach_mode:generic] 2023/12/19 01:04:35 Apply eUPF config: {InterfaceName:[eth0] XDPAttachMode:generic ApiAddress::8080 PfcpAddress::8805 PfcpNodeId:10.233.64.11 MetricsAddress::9090 N3Address:10.233.64.11 GtpPeer:[] EchoInterval:10 QerMapSize:1024 FarMapSize:1024 PdrMapSize:1024 EbpfMapResize:false HeartbeatRetries:3 HeartbeatInterval:5 HeartbeatTimeout:5 LoggingLevel:debug PfcpPeer:[open5gs-smf-pfcp] AssociationSetupTimeout:5} [90m2023/12/19 01:04:35[0m [32mINF[0m Attached XDP program to iface "eth0" (index 4) [90m2023/12/19 01:04:35[0m [32mINF[0m Starting PFCP connection: :8805 with Node ID: 10.233.64.11 and N3 address: 10.233.64.11 [GIN-debug] [WARNING] Creating an Engine instance with the Logger and Recovery middleware already attached. [GIN-debug] [WARNING] Running in "debug" mode. Switch to "release" mode in production. - using env: export GIN_MODE=release - using code: gin.SetMode(gin.ReleaseMode) [GIN-debug] GET /api/v1/health --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).InitRoutes.func1 (4 handlers) [GIN-debug] GET /api/v1/upf_pipeline --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listUpfPipeline-fm (4 handlers) [GIN-debug] GET /api/v1/xdp_stats --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).displayXdpStatistics-fm (4 handlers) [GIN-debug] GET /api/v1/packet_stats --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).displayPacketStats-fm (4 handlers) [GIN-debug] GET /api/v1/config --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).displayConfig-fm (4 handlers) [GIN-debug] POST /api/v1/config --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).editConfig-fm (4 handlers) [GIN-debug] GET /api/v1/uplink_pdr_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).getUplinkPdrValue-fm (4 handlers) [GIN-debug] PUT /api/v1/uplink_pdr_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).setUplinkPdrValue-fm (4 handlers) [GIN-debug] GET /api/v1/qer_map --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listQerMapContent-fm (4 handlers) [GIN-debug] GET /api/v1/qer_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).getQerValue-fm (4 handlers) [GIN-debug] PUT /api/v1/qer_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).setQerValue-fm (4 handlers) [GIN-debug] GET /api/v1/far_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).getFarValue-fm (4 handlers) [GIN-debug] PUT /api/v1/far_map/:id --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).setFarValue-fm (4 handlers) [GIN-debug] GET /api/v1/pfcp_associations --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listPfcpAssociations-fm (4 handlers) [GIN-debug] GET /api/v1/pfcp_associations/full --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listPfcpAssociationsFull-fm (4 handlers) [GIN-debug] GET /api/v1/pfcp_sessions --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).listPfcpSessionsFiltered-fm (4 handlers) [GIN-debug] GET /swagger/*any --> github.com/swaggo/gin-swagger.CustomWrapHandler.func1 (4 handlers) [GIN-debug] [WARNING] Creating an Engine instance with the Logger and Recovery middleware already attached. [GIN-debug] [WARNING] Running in "debug" mode. Switch to "release" mode in production. - using env: export GIN_MODE=release - using code: gin.SetMode(gin.ReleaseMode) [GIN-debug] GET /metrics --> github.com/edgecomllc/eupf/cmd/api/rest.(*ApiHandler).InitMetricsRoute.func1.1 (4 handlers) [90m2023/12/19 01:04:35[0m [32mINF[0m running on :8080 [90m2023/12/19 01:04:35[0m [32mINF[0m running on :9090 [90m2023/12/19 01:04:40[0m [33mDBG[0m Sequence ID: 1 [90m2023/12/19 01:04:40[0m [32mINF[0m Sent Association Setup Request to: open5gs-smf-pfcp [90m2023/12/19 01:04:40[0m [33mDBG[0m Received 35 bytes from 10.233.78.76:8805 [90m2023/12/19 01:04:40[0m [33mDBG[0m Handling PFCP message from 10.233.78.76:8805 [90m2023/12/19 01:04:40[0m [32mINF[0m Got Association Setup Response from: 10.233.78.76 [90m2023/12/19 01:04:40[0m [32mINF[0m Got Association Setup Response with CPFunctionFeatures from: 10.233.78.76. CPFunctionFeatures: 0 [90m2023/12/19 01:04:40[0m [32mINF[0m Saving new association: &{ID:10.233.78.76 Addr:10.233.78.76 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatRetries:0 cancelRetries:} [90m2023/12/19 01:04:42[0m [33mDBG[0m Received 16 bytes from 10.233.78.76:8805 [90m2023/12/19 01:04:42[0m [33mDBG[0m Handling PFCP message from 10.233.78.76:8805 [90m2023/12/19 01:04:42[0m [33mDBG[0m Got Heartbeat Request with TS: 2023-12-19 01:04:20 +0000 UTC, from: 10.233.78.76 [90m2023/12/19 01:04:42[0m [33mDBG[0m Sent Heartbeat Response to: 10.233.78.76 [90m2023/12/19 01:04:45[0m [33mDBG[0m Sequence ID: 2 [90m2023/12/19 01:04:45[0m [32mINF[0m Sent Association Setup Request to: open5gs-smf-pfcp [90m2023/12/19 01:04:45[0m [33mDBG[0m Stop sending Association Setup Request to open5gs-smf-pfcp [90m2023/12/19 01:04:45[0m [33mDBG[0m Received 35 bytes from 10.233.78.76:8805 [90m2023/12/19 01:04:45[0m [33mDBG[0m Handling PFCP message from 10.233.78.76:8805 [90m2023/12/19 01:04:45[0m [32mINF[0m Got Association Setup Response from: 10.233.78.76 [90m2023/12/19 01:04:45[0m [32mINF[0m Got Association Setup Response with CPFunctionFeatures from: 10.233.78.76. CPFunctionFeatures: 0 [90m2023/12/19 01:04:45[0m [31mWRN[0m Association with NodeID: 10.233.78.76 and address: 10.233.78.76 already exists [90m2023/12/19 01:04:45[0m [31mWRN[0m Session retention is not yet implemented [90m2023/12/19 01:04:45[0m [32mINF[0m Saving new association: &{ID:10.233.78.76 Addr:10.233.78.76 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatRetries:0 cancelRetries:} [90m2023/12/19 01:04:50[0m [33mDBG[0m Sent Heartbeat Request to: 10.233.78.76 [90m2023/12/19 01:04:53[0m [33mDBG[0m Received 16 bytes from 10.233.78.76:8805 [90m2023/12/19 01:04:53[0m [33mDBG[0m Handling PFCP message from 10.233.78.76:8805 [90m2023/12/19 01:04:53[0m [33mDBG[0m Got Heartbeat Request with TS: 2023-12-19 01:04:20 +0000 UTC, from: 10.233.78.76 [90m2023/12/19 01:04:53[0m [33mDBG[0m Sent Heartbeat Response to: 10.233.78.76 [90m2023/12/19 01:04:55[0m [33mDBG[0m Sent Heartbeat Request to: 10.233.78.76 [90m2023/12/19 01:04:55[0m [33mDBG[0m Received 16 bytes from 10.233.78.76:8805 [90m2023/12/19 01:04:55[0m [33mDBG[0m Handling PFCP message from 10.233.78.76:8805 [90m2023/12/19 01:04:55[0m [33mDBG[0m Got Heartbeat Response with TS: 2023-12-19 01:04:20 +0000 UTC, from: 10.233.78.76 [90m2023/12/19 01:05:00[0m [33mDBG[0m Sent Heartbeat Request to: 10.233.78.76 [90m2023/12/19 01:05:00[0m [33mDBG[0m Received 16 bytes from 10.233.78.76:8805 ```

edgecomllc / eupf