UP initiated association setup

[pirog-spb]

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]

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]

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: #497

[kade-ddnkv]

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]

✔ Solution for setting up associations in open5gs kubernetes environment.

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

manifest for headless service

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 <file>

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

Logs. SMF was started before UPF

SMF log:

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:

[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:<nil>}
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:<nil>}
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:<nil>}
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

      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:<nil> 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:<nil>}
2023/12/15 17:18:42 DBG EBPF: Put PDR Uplink: teid=2, pdrInfo={OuterHeaderRemoval:0 FarId:1 QerId:0 SdfFilter:<nil>}
2023/12/15 17:18:42 DBG EBPF: Put PDR Uplink: teid=3, pdrInfo={OuterHeaderRemoval:0 FarId:0 QerId:0 SdfFilter:<nil>}
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:<nil> 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]

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]

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:<nil>}
�[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:<nil>}
�[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