Trigger PFCP Assoc. Setup Request from SMF When Receiving Sess. Est. Request from Unassociated SMF #540

howardswe499 · 2024-03-21T09:11:19Z

howardswe499
Mar 21, 2024

Hi All,

I've been having a minor inconvenience with multiple UPFs, where if an association has already been established with the SMF (Nokia CMU in my case), and then the UPF is closed (either accidentally or intentionally), upon restarting the UPF I have to restart the SMF as well to trigger a PFCP Association Setup Request from SMF, otherwise the UPF will not be associated and thus cannot be selected to act as the UPF for the PDU Session.
Example Log output of this happening:

2024/03/21 16:22:58 INF running on :9090
2024/03/21 16:22:58 INF running on :8080
2024/03/21 16:23:23 INF Got Session Establishment Request from: 10.246.112.62.
2024/03/21 16:23:23 INF Rejecting Session Establishment Request from: 10.246.112.62 (no association)
2024/03/21 16:23:29 INF Got Session Establishment Request from: 10.246.112.62.
2024/03/21 16:23:29 INF Rejecting Session Establishment Request from: 10.246.112.62 (no association)
2024/03/21 16:23:34 INF Got Session Establishment Request from: 10.246.112.62.
2024/03/21 16:23:34 INF Rejecting Session Establishment Request from: 10.246.112.62 (no association)
2024/03/21 16:23:40 INF Got Session Establishment Request from: 10.246.112.62.
2024/03/21 16:23:40 INF Rejecting Session Establishment Request from: 10.246.112.62 (no association)
...

I was testing around with other UPFs for my integration project, when I stumbled upon OAI-VPP-UPF and to my surprise, when faced with the same scenario, OAI-UPF was able to force the SMF to re-associate with it. I compared eUPF vs OAI-UPF's PFCP signaling, and noticed that OAI-UPF had extra fields of "Node ID" and "Error Report" in its PFCP Session Establishment Response. Perhaps this is what is triggering the SMF to re-associate?

eUPF PFCP Session Establishment Reply

OAI-UPF PFCP Session Establishment Reply

Best Regards,
Howard

pirog-spb · 2024-03-22T06:48:44Z

pirog-spb
Mar 22, 2024
Maintainer

Hi Howard @howardswe499,

Could you please try eUPF based on branch mentioned in #539? This issue is nearly to be released, but in order not to wait release you are welcome to try current development branch.

-- BR, Alex

1 reply

howardswe499 Mar 22, 2024
Author

Hi Alex,

Cool, I see you guys have been working on this feature already. How telepathic 😁
I'll try it out next week.

BR
Howard

howardswe499 · 2024-03-25T02:24:59Z

howardswe499
Mar 25, 2024
Author

Hi @pirog-spb ,

On branch #539 , when eUPF received a Session Establishment Request, its response included Node ID field, which seems to trigger Association Setup Request from SMF, resulting in successful re-association.

However, SMF seems to send a Session Deletion Request before sending an Establishment Request, to which eUPF responds with a failure due to no Assocation, of which results in failed PDU session establishment and skipping of 1 IP from IP pool as a result of the failed PDU session establishment.

UERANSIM Log

[2024-03-25 09:45:34.812] [nas] [info] PDU Session establishment is successful PSI[1]
[2024-03-25 09:45:34.858] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 10.246.115.220] is up.
^Croot@da-ueransim:~/UERANSIM/config/[redacted]# ../../build/nr-ue -c [redacted] 
UERANSIM v3.2.6
[2024-03-25 09:46:42.076] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2024-03-25 09:46:42.077] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2024-03-25 09:46:42.078] [nas] [info] Selected plmn[001/01]
[2024-03-25 09:46:42.078] [rrc] [info] Selected cell plmn[001/01] tac[redacted] category[SUITABLE]
[2024-03-25 09:46:42.078] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2024-03-25 09:46:42.078] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2024-03-25 09:46:42.078] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2024-03-25 09:46:42.078] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-03-25 09:46:42.078] [nas] [debug] Sending Initial Registration
[2024-03-25 09:46:42.079] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2024-03-25 09:46:42.079] [rrc] [debug] Sending RRC Setup Request
[2024-03-25 09:46:42.080] [rrc] [info] RRC connection established
[2024-03-25 09:46:42.080] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2024-03-25 09:46:42.080] [nas] [info] UE switches to state [CM-CONNECTED]
[2024-03-25 09:46:42.185] [nas] [debug] Authentication Request received
[2024-03-25 09:46:42.185] [nas] [debug] Sending Authentication Failure due to SQN out of range
[2024-03-25 09:46:42.328] [nas] [debug] Authentication Request received
[2024-03-25 09:46:42.362] [nas] [debug] Security Mode Command received
[2024-03-25 09:46:42.362] [nas] [debug] Selected integrity[2] ciphering[0]
[2024-03-25 09:46:42.602] [nas] [debug] Registration accept received
[2024-03-25 09:46:42.603] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2024-03-25 09:46:42.603] [nas] [debug] Sending Registration Complete
[2024-03-25 09:46:42.603] [nas] [info] Initial Registration is successful
[2024-03-25 09:46:42.603] [nas] [debug] Sending PDU Session Establishment Request
[2024-03-25 09:46:42.603] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-03-25 09:46:42.824] [nas] [debug] Configuration Update Command received
[2024-03-25 09:46:43.023] [nas] [error] PDU Session Establishment Reject received [REQUEST_REJECTED_UNSPECIFIED] # PDU sess. est. rejected
[2024-03-25 09:46:43.176] [nas] [debug] Sending PDU Session Establishment Request
[2024-03-25 09:46:43.176] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-03-25 09:46:43.326] [nas] [debug] PDU Session Establishment Accept received
[2024-03-25 09:46:43.326] [nas] [info] PDU Session establishment is successful PSI[1]
[2024-03-25 09:46:43.374] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 10.246.115.222] is up. # 10.246.115.221 is skipped

Here is Session Deletion Request and corresponding Response. The Session Deletion Response also does not contain Node ID field. Perhaps this could be the reason?

Here are the logs from my testing. Core signaling pcap/further testing can be provided on request.

Logs

============
=== eUPF ===
============
root@da-eupf:~/eupf# ./bin/eupf
2024/03/25 09:44:14 Startup config: map[api_address::8080 echo_interval:10 far_map_size:1024 feature_ftup:true feature_ueip:true gtp_peer:[] heartbeat_interval:60 heartbeat_retries:3 heartbeat_timeout:60 interface_name:[ens161 ens224 ens192] logging_level:info metrics_address::9090 n3_address:172.16.13.5 pdr_map_size:1024 pfcp_address:192.168.102.55:8805 pfcp_node_id:192.168.102.55 qer_map_size:1024 resize_ebpf_maps:false teid_pool:65536 ueip_pool:10.60.0.0/24 xdp_attach_mode:generic]
2024/03/25 09:44:14 Apply eUPF config: {InterfaceName:[ens161 ens224 ens192] XDPAttachMode:generic ApiAddress::8080 PfcpAddress:192.168.102.55:8805 PfcpNodeId:192.168.102.55 MetricsAddress::9090 N3Address:172.16.13.5 GtpPeer:[] EchoInterval:10 QerMapSize:1024 FarMapSize:1024 PdrMapSize:1024 EbpfMapResize:false HeartbeatRetries:3 HeartbeatInterval:60 HeartbeatTimeout:60 LoggingLevel:info UEIPPool:10.60.0.0/24 FTEIDPool:65536 FeatureUEIP:true FeatureFTUP:true}
2024/03/25 09:44:14 INF Attached XDP program to iface "ens161" (index 8)
2024/03/25 09:44:14 INF Attached XDP program to iface "ens224" (index 9)
2024/03/25 09:44:14 INF Attached XDP program to iface "ens192" (index 7)
2024/03/25 09:44:14 INF Initialize resources: UEIP pool (CIDR: "10.60.0.0/24"), TEID pool (size: 65536)
2024/03/25 09:44:14 INF Starting PFCP connection: 192.168.102.55:8805 with Node ID: 192.168.102.55 and N3 address: 172.16.13.5
[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/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)
2024/03/25 09:44:14 INF running on :8080
2024/03/25 09:44:14 INF running on :9090
2024/03/25 09:44:16 INF Got Association Setup Request from: 192.168.102.52. 

2024/03/25 09:44:16 INF 
Association Setup Request: # Unrelated SMF
  Node ID: 192.168.102.52
  Recovery Time: 2024-03-22 12:08:37 +0800 CST

2024/03/25 09:44:16 INF Saving new association: &{ID:192.168.102.52 Addr:192.168.102.52 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatChannel:0xc000100f60 FailedHeartbeats:0 HeartbeatsActive:false Mutex:{state:0 sema:0}}
2024/03/25 09:44:25 INF Got Session Deletion Request from: 10.246.112.62. 

2024/03/25 09:44:25 INF Rejecting Session Deletion Request from: 10.246.112.62 (no association)
2024/03/25 09:44:25 INF Got Session Establishment Request from: 10.246.112.62.
2024/03/25 09:44:25 INF Rejecting Session Establishment Request from: 10.246.112.62 (no association)
2024/03/25 09:44:25 INF Got Association Setup Request from: 10.246.112.62. 

2024/03/25 09:44:25 INF 
Association Setup Request: # CMU SMF
  Node ID: 10.246.112.62
  Recovery Time: 2024-03-25 09:41:40 +0800 CST

2024/03/25 09:44:25 INF Saving new association: &{ID:10.246.112.62 Addr:10.246.112.62 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatChannel:0xc000100fc0 FailedHeartbeats:0 HeartbeatsActive:false Mutex:{state:0 sema:0}}
2024/03/25 09:44:25 INF Got Session Establishment Request from: 10.246.112.62.
2024/03/25 09:44:25 INF 
Session Establishment Request:
  CreatePDR ID: 18944 
    Outer Header Removal: 1 
    FAR ID: 327680 
    QER ID: 80 
    QER ID: 4117 
    URR ID: 1610612737 
    Source Interface: 0 
    TEID: 0 
    Ipv4: <nil> 
    Ipv6: <nil> 
    UE IPv4 Address: 10.246.115.218 
    SDF Filter: permit out ip from any to any 
  CreatePDR ID: 35328 
    FAR ID: 537198592 
    QER ID: 80 
    QER ID: 4117 
    URR ID: 1610612737 
    Source Interface: 1 
    UE IPv4 Address: 10.246.115.218 
    SDF Filter:  
  CreateFAR ID: 327680 
    Apply Action: [2] 
    Forwarding Parameters:
      Network Instance: 5gtest1 
  CreateFAR ID: 537198592 
    Apply Action: [4] 
    Forwarding Parameters:
      Network Instance:n3-realm 
    BAR ID: 5 
  CreateQER ID: 80 
    Gate Status DL: 0 
    Gate Status UL: 0 
    Max Bitrate DL: 5000000 
    Max Bitrate UL: 5000000 
  CreateQER ID: 4117 
    Gate Status DL: 0 
    Gate Status UL: 0 
    QFI: 5 
  CreateURR ID: 1610612737 
    Measurement Method: 3 
  CreateURR ID: 1073741829 
    Measurement Method: 2 
    Volume Threshold: &{Flags:1 TotalVolume:104857600 UplinkVolume:0 DownlinkVolume:0} 
  CreateURR ID: 1073741825 
    Measurement Method: 2 
  CreateBAR ID: 5
    Downlink Data Notification Delay: 0s 

2024/03/25 09:44:25 INF WARN: No OuterHeaderCreation
2024/03/25 09:44:25 INF Saving FAR info to session: 327680, {Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:84742316 TransportLevelMarking:0}
2024/03/25 09:44:25 INF WARN: No OuterHeaderCreation
2024/03/25 09:44:25 INF Saving FAR info to session: 537198592, {Action:4 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:84742316 TransportLevelMarking:0}
2024/03/25 09:44:25 INF Saving QER info to session: 80, {GateStatusUL:0 GateStatusDL:0 Qfi:0 MaxBitrateUL:705032704 MaxBitrateDL:705032704 StartUL:0 StartDL:0}
2024/03/25 09:44:25 INF Saving QER info to session: 4117, {GateStatusUL:0 GateStatusDL:0 Qfi:5 MaxBitrateUL:0 MaxBitrateDL:0 StartUL:0 StartDL:0}
2024/03/25 09:44:25 Matched groups: [permit out ip from any to any ip any   any  ]
2024/03/25 09:44:25 Matched groups: []
2024/03/25 09:44:25 ERR SDFFilter err: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp|\d+) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to (assigned|any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$
2024/03/25 09:44:25 ERR error extracting PDR info: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp|\d+) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to (assigned|any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$
2024/03/25 09:44:25 INF Session Establishment Request from 10.246.112.62 accepted.
2024/03/25 09:44:26 INF Got Session Modification Request from: 10.246.112.62. 

2024/03/25 09:44:26 INF Finding association for 10.246.112.62
2024/03/25 09:44:26 INF Finding session 2
2024/03/25 09:44:26 INF 
Session Modification Request:
  UpdateFAR ID: 537198592 
    Apply Action: [2] 
    Update forwarding Parameters:
      Network Instance:n3-realm 
      Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:2 IPv4Address:172.16.13.1 IPv6Address:<nil> PortNumber:0 CTag:0 STag:0} 

2024/03/25 09:44:26 INF Updating FAR info: 537198592, {FarInfo:{Action:2 OuterHeaderCreation:1 Teid:2 RemoteIP:17633452 LocalIP:84742316 TransportLevelMarking:0} GlobalId:1}
^C2024/03/25 09:45:27 INF Received signal, exiting program..
2024/03/25 09:45:27 WRN Error reading from UDP socket: read udp 192.168.102.55:8805: use of closed network connection
root@da-eupf:~/eupf#

======================
=== UERANSIM (RAN) ===
======================
UERANSIM v3.2.6
[trimmed]
[2024-03-25 09:44:24.747] [rrc] [debug] UE[2] new signal detected
[2024-03-25 09:44:24.750] [rrc] [info] RRC Setup for UE[2]
[2024-03-25 09:44:24.751] [ngap] [debug] Initial NAS message received from UE[2]
[2024-03-25 09:44:25.026] [ngap] [debug] UE Context Release Command received
[2024-03-25 09:44:25.026] [rrc] [info] Releasing RRC connection for UE[1]
[2024-03-25 09:44:25.280] [ngap] [debug] Initial Context Setup Request received
[2024-03-25 09:44:26.126] [ngap] [info] PDU session resource(s) setup for UE[2] count[1]
[2024-03-25 09:45:28.072] [rls] [debug] UE[2] signal lost
[trimmed]
=====================
=== UERANSIM (UE) ===
=====================
^Croot@da-ueransim:~/UERANSIM/config/[redacted]# ../../build/nr-ue -c [redacted] 
UERANSIM v3.2.6
[2024-03-25 09:44:24.747] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2024-03-25 09:44:24.748] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2024-03-25 09:44:24.748] [nas] [info] Selected plmn[001/01]
[2024-03-25 09:44:24.748] [rrc] [info] Selected cell plmn[001/01] tac[redacted]  category[SUITABLE]
[2024-03-25 09:44:24.748] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2024-03-25 09:44:24.749] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2024-03-25 09:44:24.749] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2024-03-25 09:44:24.749] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-03-25 09:44:24.749] [nas] [debug] Sending Initial Registration
[2024-03-25 09:44:24.749] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2024-03-25 09:44:24.749] [rrc] [debug] Sending RRC Setup Request
[2024-03-25 09:44:24.750] [rrc] [info] RRC connection established
[2024-03-25 09:44:24.750] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2024-03-25 09:44:24.750] [nas] [info] UE switches to state [CM-CONNECTED]
[2024-03-25 09:44:24.851] [nas] [debug] Authentication Request received
[2024-03-25 09:44:24.851] [nas] [debug] Sending Authentication Failure due to SQN out of range
[2024-03-25 09:44:24.994] [nas] [debug] Authentication Request received
[2024-03-25 09:44:25.042] [nas] [debug] Security Mode Command received
[2024-03-25 09:44:25.042] [nas] [debug] Selected integrity[2] ciphering[0]
[2024-03-25 09:44:25.281] [nas] [debug] Registration accept received
[2024-03-25 09:44:25.281] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2024-03-25 09:44:25.281] [nas] [debug] Sending Registration Complete
[2024-03-25 09:44:25.281] [nas] [info] Initial Registration is successful
[2024-03-25 09:44:25.281] [nas] [debug] Sending PDU Session Establishment Request
[2024-03-25 09:44:25.281] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-03-25 09:44:25.502] [nas] [debug] Configuration Update Command received
[2024-03-25 09:44:25.623] [nas] [error] PDU Session Establishment Reject received [REQUEST_REJECTED_UNSPECIFIED]
[2024-03-25 09:44:25.847] [nas] [debug] Sending PDU Session Establishment Request
[2024-03-25 09:44:25.847] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-03-25 09:44:26.127] [nas] [debug] PDU Session Establishment Accept received
[2024-03-25 09:44:26.127] [nas] [info] PDU Session establishment is successful PSI[1]
[2024-03-25 09:44:26.177] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 10.246.115.218] is up.
^Croot@da-ueransim:~/UERANSIM/config/

Cheers
Howard

0 replies

pirog-spb · 2024-03-25T20:27:09Z

pirog-spb
Mar 25, 2024
Maintainer

Hi @howardswe499,

Thank you for the detailed feedback.

I fixed NodeID in Session Modification and Session Deletion messages. Now this field should be in every session message from eUPF.

Please try it on #539 branch.

-- BR, Alex

1 reply

howardswe499 Mar 28, 2024
Author

Hi Alex,

You're welcome! Unfortunately I cannot test the newest commit yet, due to running into some technical difficulties with the CMU, but I'll keep you updated once I get to test Session Deletion message.

BR
Howard

howardswe499 · 2024-04-08T02:17:18Z

howardswe499
Apr 8, 2024
Author

Hi @pirog-spb ,

Sorry for the late reply.

So, the fix on commit 76b6c4a2df0068cf751a38e4e6bf0b7cd7fe9499 successfully added Node ID field to Session Deletion Response, but this doesn't seem to trigger SMF Association Setup Request. It seems to only be triggered by Session Establishment Response.

Session Deletion Response (With Node ID)

Association Setup Request Triggered by Session Establishment Response

As seen in logs, UE was still assigned IP address that skipped 1 value.

Logs

=================
=== Eupf Logs ===
=================
[trimmed]
2024/04/08 09:50:09 INF Rejecting Session Deletion Request from: 10.246.112.62 (no association)
2024/04/08 09:50:09 INF Got Session Establishment Request from: 10.246.112.62.
2024/04/08 09:50:09 INF Rejecting Session Establishment Request from: 10.246.112.62 (no association)
2024/04/08 09:50:09 INF Got Association Setup Request from: 10.246.112.62. 

2024/04/08 09:50:09 INF 
Association Setup Request:
  Node ID: 10.246.112.62
  Recovery Time: 2024-04-03 19:17:12 +0800 CST

2024/04/08 09:50:09 INF Saving new association: &{ID:10.246.112.62 Addr:10.246.112.62 NextSessionID:1 NextSequenceID:1 Sessions:map[] HeartbeatChannel:0xc0001024e0 FailedHeartbeats:0 HeartbeatsActive:false Mutex:{state:0 sema:0}}
2024/04/08 09:50:10 INF Got Session Establishment Request from: 10.246.112.62.
2024/04/08 09:50:10 INF 
Session Establishment Request:
  CreatePDR ID: 18944 
    Outer Header Removal: 1 
    FAR ID: 327680 
    QER ID: 1 
    QER ID: 4117 
    URR ID: 1610612737 
    Source Interface: 0 
    TEID: 0 
    Ipv4: <nil> 
    Ipv6: <nil> 
    UE IPv4 Address: 10.246.115.221 
    SDF Filter: permit out ip from any to any 
  CreatePDR ID: 35328 
    FAR ID: 537198592 
    QER ID: 1 
    QER ID: 4117 
    URR ID: 1610612737 
    Source Interface: 1 
    UE IPv4 Address: 10.246.115.221 
    SDF Filter:  
  CreateFAR ID: 327680 
    Apply Action: [2] 
    Forwarding Parameters:
      Network Instance: 5gtest1 
  CreateFAR ID: 537198592 
    Apply Action: [4] 
    Forwarding Parameters:
      Network Instance:n3-realm 
    BAR ID: 5 
  CreateQER ID: 1 
    Gate Status DL: 0 
    Gate Status UL: 0 
    Max Bitrate DL: 5000000 
    Max Bitrate UL: 5000000 
  CreateQER ID: 4117 
    Gate Status DL: 0 
    Gate Status UL: 0 
    QFI: 5 
  CreateURR ID: 1610612737 
    Measurement Method: 3 
  CreateURR ID: 1073741829 
    Measurement Method: 2 
    Volume Threshold: &{Flags:1 TotalVolume:104857600 UplinkVolume:0 DownlinkVolume:0} 
  CreateURR ID: 1073741825 
    Measurement Method: 2 
  CreateBAR ID: 5
    Downlink Data Notification Delay: 0s 

2024/04/08 09:50:10 INF WARN: No OuterHeaderCreation
2024/04/08 09:50:10 INF Saving FAR info to session: 327680, {Action:2 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:929474752 TransportLevelMarking:0}
2024/04/08 09:50:10 INF WARN: No OuterHeaderCreation
2024/04/08 09:50:10 INF Saving FAR info to session: 537198592, {Action:4 OuterHeaderCreation:0 Teid:0 RemoteIP:0 LocalIP:929474752 TransportLevelMarking:0}
2024/04/08 09:50:10 INF Saving QER info to session: 1, {GateStatusUL:0 GateStatusDL:0 Qfi:0 MaxBitrateUL:705032704 MaxBitrateDL:705032704 StartUL:0 StartDL:0}
2024/04/08 09:50:10 INF Saving QER info to session: 4117, {GateStatusUL:0 GateStatusDL:0 Qfi:5 MaxBitrateUL:0 MaxBitrateDL:0 StartUL:0 StartDL:0}
2024/04/08 09:50:10 Matched groups: [permit out ip from any to any ip any   any  ]
2024/04/08 09:50:10 Matched groups: []
2024/04/08 09:50:10 ERR SDFFilter err: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp|\d+) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to (assigned|any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$
2024/04/08 09:50:10 ERR error extracting PDR info: SDF Filter: bad formatting. Should be compatible with regexp: ^permit out (icmp|ip|tcp|udp|\d+) from (any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))? to (assigned|any|[\d.]+|[\da-fA-F:]+)(?:/(\d+))?(?: (\d+|\d+-\d+))?$
2024/04/08 09:50:10 INF Session Establishment Request from 10.246.112.62 accepted.
2024/04/08 09:50:10 INF Got Session Modification Request from: 10.246.112.62. 

2024/04/08 09:50:10 INF Finding association for 10.246.112.62
2024/04/08 09:50:10 INF Finding session 2
2024/04/08 09:50:10 INF 
Session Modification Request:
  UpdateFAR ID: 537198592 
    Apply Action: [2] 
    Update forwarding Parameters:
      Network Instance:n3-realm 
      Outer Header Creation: &{OuterHeaderCreationDescription:256 TEID:4 IPv4Address:172.16.13.1 IPv6Address:<nil> PortNumber:0 CTag:0 STag:0} 

2024/04/08 09:50:10 INF Updating FAR info: 537198592, {FarInfo:{Action:2 OuterHeaderCreation:1 Teid:4 RemoteIP:17633452 LocalIP:929474752 TransportLevelMarking:0} GlobalId:1}

=====================
=== UERANSIM (UE) ===
=====================
UERANSIM v3.2.6
[2024-04-08 09:50:08.603] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2024-04-08 09:50:08.605] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2024-04-08 09:50:08.606] [nas] [info] Selected plmn[001/01]
[2024-04-08 09:50:08.606] [rrc] [info] Selected cell plmn[001/01] tac[redacted] category[SUITABLE]
[2024-04-08 09:50:08.606] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2024-04-08 09:50:08.606] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2024-04-08 09:50:08.606] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2024-04-08 09:50:08.606] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-04-08 09:50:08.606] [nas] [debug] Sending Initial Registration
[2024-04-08 09:50:08.606] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2024-04-08 09:50:08.607] [rrc] [debug] Sending RRC Setup Request
[2024-04-08 09:50:08.608] [rrc] [info] RRC connection established
[2024-04-08 09:50:08.609] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2024-04-08 09:50:08.609] [nas] [info] UE switches to state [CM-CONNECTED]
[2024-04-08 09:50:08.711] [nas] [debug] Authentication Request received
[2024-04-08 09:50:08.712] [nas] [debug] Sending Authentication Failure due to SQN out of range
[2024-04-08 09:50:08.811] [nas] [debug] Authentication Request received
[2024-04-08 09:50:08.868] [nas] [debug] Security Mode Command received
[2024-04-08 09:50:08.868] [nas] [debug] Selected integrity[2] ciphering[0]
[2024-04-08 09:50:09.180] [nas] [debug] Registration accept received
[2024-04-08 09:50:09.180] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2024-04-08 09:50:09.180] [nas] [debug] Sending Registration Complete
[2024-04-08 09:50:09.180] [nas] [info] Initial Registration is successful
[2024-04-08 09:50:09.180] [nas] [debug] Sending PDU Session Establishment Request
[2024-04-08 09:50:09.180] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-04-08 09:50:09.407] [nas] [debug] Configuration Update Command received
[2024-04-08 09:50:10.031] [nas] [error] PDU Session Establishment Reject received [REQUEST_REJECTED_UNSPECIFIED]
[2024-04-08 09:50:10.805] [nas] [debug] Sending PDU Session Establishment Request
[2024-04-08 09:50:10.805] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-04-08 09:50:10.934] [nas] [debug] PDU Session Establishment Accept received
[2024-04-08 09:50:10.935] [nas] [info] PDU Session establishment is successful PSI[1]
[2024-04-08 09:50:10.998] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 10.246.115.221] is up.

======================
=== UERANSIM (RAN) ===
======================
UERANSIM v3.2.6
[trimmed]
[2024-04-08 09:50:08.604] [rrc] [debug] UE[4] new signal detected
[2024-04-08 09:50:08.607] [rrc] [info] RRC Setup for UE[4]
[2024-04-08 09:50:08.608] [ngap] [debug] Initial NAS message received from UE[4]
[2024-04-08 09:50:08.844] [ngap] [debug] UE Context Release Command received
[2024-04-08 09:50:08.845] [rrc] [info] Releasing RRC connection for UE[2]
[2024-04-08 09:50:09.179] [ngap] [debug] Initial Context Setup Request received
[2024-04-08 09:50:10.007] [rls] [debug] UE[3] signal lost
[2024-04-08 09:50:10.934] [ngap] [info] PDU session resource(s) setup for UE[4] count[1]
[trimmed]

However, after thinking about it, I think the IP being skipped isn't actually caused by Session Deletion Request not triggering Association, but is rather due to the 1st Session Establishment Request being rejected. My apologies for the confusion caused!

Cheers,
Howard

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Trigger PFCP Assoc. Setup Request from SMF When Receiving Sess. Est. Request from Unassociated SMF #540

{{title}}

Replies: 4 comments 2 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Trigger PFCP Assoc. Setup Request from SMF When Receiving Sess. Est. Request from Unassociated SMF #540

howardswe499 Mar 21, 2024

Replies: 4 comments · 2 replies

pirog-spb Mar 22, 2024 Maintainer

howardswe499 Mar 22, 2024 Author

howardswe499 Mar 25, 2024 Author

pirog-spb Mar 25, 2024 Maintainer

howardswe499 Mar 28, 2024 Author

howardswe499 Apr 8, 2024 Author

howardswe499
Mar 21, 2024

Replies: 4 comments 2 replies

pirog-spb
Mar 22, 2024
Maintainer

howardswe499 Mar 22, 2024
Author

howardswe499
Mar 25, 2024
Author

pirog-spb
Mar 25, 2024
Maintainer

howardswe499 Mar 28, 2024
Author

howardswe499
Apr 8, 2024
Author