UPF Integration with Nokia CMU - PDU/PFCP Session Establishment problem

Q/A
,
#1

Overview of devices used:

  • Free5GC v3.4.0 on Ubuntu 22.04.3 (VM)
  • UERANSIM v3.2.6 on Ubuntu 22.04.3 (VM)
  • Nokia CMU 22.10.R1

IP List:

  • UERANSIM IP: 192.168.99.11
  • Free5GC UPF IP: 192.168.99.22
  • CMU AMF IP: 10.246.112.18
  • CMU SMF IP: 10.246.112.62

Hello all,

I am trying to integrate F5GC UPF with Nokia CMU.
Currently, UPF and CMU SMF is able to create PFCP Association.
But when I try to connect a UE to CMU via F5GC UPF using UERANSIM’s UE & RAN features, the following errors occur, and the UE is stuck in a perpetual loop of attempting to establish a PDU session:

Logs

UE

user1@ueransim:~/UERANSIM/config/[REDACTED]$ sudo ../../build/nr-ue -c ./[REDACTED]
[sudo] password for user1: 
UERANSIM v3.2.6
[2024-02-19 16:58:41.051] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2024-02-19 16:58:41.052] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2024-02-19 16:58:41.052] [nas] [info] Selected plmn[001/01]
[2024-02-19 16:58:41.052] [rrc] [info] Selected cell plmn[001/01] tac[REDACTED] category[SUITABLE]
[2024-02-19 16:58:41.052] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2024-02-19 16:58:41.052] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2024-02-19 16:58:41.052] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2024-02-19 16:58:41.052] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-19 16:58:41.053] [nas] [debug] Sending Initial Registration
[2024-02-19 16:58:41.053] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2024-02-19 16:58:41.053] [rrc] [debug] Sending RRC Setup Request
[2024-02-19 16:58:41.053] [rrc] [info] RRC connection established
[2024-02-19 16:58:41.053] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2024-02-19 16:58:41.053] [nas] [info] UE switches to state [CM-CONNECTED]
[2024-02-19 16:58:41.206] [nas] [debug] Authentication Request received
[2024-02-19 16:58:41.206] [nas] [debug] Sending Authentication Failure due to SQN out of range
[2024-02-19 16:58:41.307] [nas] [debug] Authentication Request received
[2024-02-19 16:58:41.327] [nas] [debug] Security Mode Command received
[2024-02-19 16:58:41.327] [nas] [debug] Selected integrity[2] ciphering[0]
[2024-02-19 16:58:41.688] [nas] [debug] Registration accept received
[2024-02-19 16:58:41.688] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2024-02-19 16:58:41.688] [nas] [debug] Sending Registration Complete
[2024-02-19 16:58:41.688] [nas] [info] Initial Registration is successful
[2024-02-19 16:58:41.688] [nas] [debug] Sending PDU Session Establishment Request
[2024-02-19 16:58:41.688] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-19 16:58:41.913] [nas] [debug] Configuration Update Command received
[2024-02-19 16:58:42.188] [nas] [error] PDU Session Establishment Reject received [REACTIVATION_REQUESTED]
[2024-02-19 16:58:43.275] [nas] [debug] Sending PDU Session Establishment Request
[2024-02-19 16:58:43.275] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-19 16:58:43.658] [nas] [error] PDU Session Establishment Reject received [REACTIVATION_REQUESTED]
[2024-02-19 16:58:44.389] [nas] [debug] Sending PDU Session Establishment Request
[2024-02-19 16:58:44.389] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-19 16:58:44.659] [nas] [error] PDU Session Establishment Reject received [REACTIVATION_REQUESTED]
^Cuser1@ueransim:~/UERANSIM/config/[REDACTED]$

RAN

user1@ueransim:~/UERANSIM/config/[REDACTED]$ ../../build/nr-gnb -c ./[REDACTED]
UERANSIM v3.2.6
[2024-02-19 16:58:36.899] [sctp] [info] Trying to establish SCTP connection... (10.246.112.18:38412)
[2024-02-19 16:58:36.928] [sctp] [info] SCTP connection established (10.246.112.18:38412)
[2024-02-19 16:58:36.929] [sctp] [debug] SCTP association setup ascId[76]
[2024-02-19 16:58:36.929] [ngap] [debug] Sending NG Setup Request
[2024-02-19 16:58:36.939] [ngap] [debug] NG Setup Response received
[2024-02-19 16:58:36.939] [ngap] [info] NG Setup procedure is successful
[2024-02-19 16:58:41.051] [rrc] [debug] UE[1] new signal detected
[2024-02-19 16:58:41.053] [rrc] [info] RRC Setup for UE[1]
[2024-02-19 16:58:41.054] [ngap] [debug] Initial NAS message received from UE[1]
[2024-02-19 16:58:41.687] [ngap] [debug] Initial Context Setup Request received
[2024-02-19 16:58:42.130] [ngap] [error] PDU session resource could not setup: Uplink TNL information is missing
[2024-02-19 16:58:42.130] [ngap] [error] PDU session resource(s) setup was failed for UE[1] count[1]
[2024-02-19 16:58:43.630] [ngap] [error] PDU session resource could not setup: Uplink TNL information is missing
[2024-02-19 16:58:43.630] [ngap] [error] PDU session resource(s) setup was failed for UE[1] count[1]
[2024-02-19 16:58:44.628] [ngap] [error] PDU session resource could not setup: Uplink TNL information is missing
[2024-02-19 16:58:44.628] [ngap] [error] PDU session resource(s) setup was failed for UE[1] count[1]
[2024-02-19 16:58:46.444] [rls] [debug] UE[1] signal lost
^Cuser1@ueransim:~/UERANSIM/config/[REDACTED]$

F5GC UPF (debug):
sudo -E ./bin/upf was used to run UPF independently.
Note that the CMU required a service restart to reassociate with new UPFs, which is why there are 2 instances of handleAssociationReleaseRequest in the beginning. From handleAssociationSetupRequest is where relevant information begins.

user1@free5gc-2-upf:~/free5gc$ sudo -E ./bin/upf -c ./config/[REDACTED] -l ./log/free5gc.log
2024-02-19T17:32:30.951456866+08:00 [INFO][UPF][Main] UPF version:  
        free5GC version: v3.4.0
        build time:      2024-02-19T08:16:48Z
        commit hash:     +d70e69b
        commit time:     2024-02-17T03:03:47Z
        go version:      go1.18.10 linux/amd64
2024-02-19T17:32:30.951737475+08:00 [INFO][UPF][CFG] Read config from [./config/[REDACTED]]
2024-02-19T17:32:30.952329384+08:00 [INFO][UPF][CFG] ==================================================
2024-02-19T17:32:30.952413822+08:00 [INFO][UPF][CFG] (*factory.Config)(0xc000498d20)({
        Version: (string) (len=5) "1.0.3",
        Description: (string) (len=31) "UPF initial local configuration",
        Pfcp: (*factory.Pfcp)(0xc000096990)({
                Addr: (string) (len=13) "192.168.99.22",
                NodeID: (string) (len=13) "192.168.99.22",
                RetransTimeout: (time.Duration) 1s,
                MaxRetrans: (uint8) 3
        }),
        Gtpu: (*factory.Gtpu)(0xc000096b40)({
                Forwarder: (string) (len=5) "gtp5g",
                IfList: ([]factory.IfInfo) (len=1 cap=1) {
                        (factory.IfInfo) {
                                Addr: (string) (len=13) "192.168.99.22",
                                Type: (string) (len=2) "N3",
                                Name: (string) (len=8) "n3-realm",
                                IfName: (string) "",
                                MTU: (uint32) 0
                        }
                }
        }),
        DnnList: ([]factory.DnnList) (len=1 cap=1) {
                (factory.DnnList) {
                        Dnn: (string) (len=7) "[REDACTED]",
                        Cidr: (string) (len=17) "10.246.115.240/29",
                        NatIfName: (string) ""
                }
        },
        Logger: (*factory.Logger)(0xc00048d580)({
                Enable: (bool) true,
                Level: (string) (len=5) "debug",
                ReportCaller: (bool) false
        })
})
2024-02-19T17:32:30.952536535+08:00 [INFO][UPF][CFG] ==================================================
2024-02-19T17:32:30.952559459+08:00 [INFO][UPF][Main] Log level is set to [debug]
2024-02-19T17:32:30.952609503+08:00 [INFO][UPF][Main] Report Caller is set to [false]
2024-02-19T17:32:30.952692069+08:00 [INFO][UPF][Main] starting Gtpu Forwarder [gtp5g]
2024-02-19T17:32:30.952903216+08:00 [INFO][UPF][Main] GTP Address: "192.168.99.22:2152"
2024-02-19T17:32:30.969681958+08:00 [INFO][UPF][BUFF] buff netlink server started
2024-02-19T17:32:30.970442117+08:00 [INFO][UPF][Perio] perio server started
2024-02-19T17:32:30.970487958+08:00 [INFO][UPF][Gtp5g] Forwarder started
2024-02-19T17:32:30.970787430+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] starting pfcp server
2024-02-19T17:32:30.973793558+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] pfcp server started
2024-02-19T17:32:30.973848685+08:00 [INFO][UPF][Main] UPF started
2024-02-19T17:32:39.959548766+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-3] start timer(4s)
2024-02-19T17:32:39.959756456+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-3] recv req - rxTrFound(false)
2024-02-19T17:32:39.959793379+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleAssociationReleaseRequest not supported
2024-02-19T17:32:43.962975398+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-3] timeout, delete rxtr
2024-02-19T17:32:44.692474132+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-3] start timer(4s)
2024-02-19T17:32:44.692651627+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-3] recv req - rxTrFound(false)
2024-02-19T17:32:44.692697937+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleAssociationReleaseRequest not supported
2024-02-19T17:32:44.829762581+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-2] start timer(4s)
2024-02-19T17:32:44.829875795+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-2] recv req - rxTrFound(false)
2024-02-19T17:32:44.829909752+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleAssociationSetupRequest
2024-02-19T17:32:44.829951678+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] remote nodeid: 10.246.112.62
2024-02-19T17:32:44.830068468+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62] New node
2024-02-19T17:32:44.830206366+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-2] send rsp
2024-02-19T17:32:44.841764695+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] start timer(4s)
2024-02-19T17:32:44.841856691+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] recv req - rxTrFound(false)
2024-02-19T17:32:44.841874814+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleHeartbeatRequest
2024-02-19T17:32:44.842029370+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] send rsp
2024-02-19T17:32:48.696568742+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-3] timeout, delete rxtr
2024-02-19T17:32:48.830090810+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-2] timeout, delete rxtr
2024-02-19T17:32:48.842850571+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] timeout, delete rxtr
2024-02-19T17:32:57.054058780+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114113] start timer(4s)
2024-02-19T17:32:57.054254303+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114113] recv req - rxTrFound(false)
2024-02-19T17:32:57.054349261+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleSessionEstablishmentRequest
2024-02-19T17:32:57.054390547+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] remote nodeid: 10.246.112.62
2024-02-19T17:32:57.054426749+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] fseid.SEID: 0x11110
2024-02-19T17:32:57.054491350+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62][CPSEID:0x11110][UPSEID:0x1] New session
2024-02-19T17:32:57.057431157+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114113] send rsp
2024-02-19T17:32:57.302943014+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114114] start timer(4s)
2024-02-19T17:32:57.303061800+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114114] recv req - rxTrFound(false)
2024-02-19T17:32:57.303090825+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleSessionDeletionRequest
2024-02-19T17:32:57.303158040+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62][CPSEID:0x11110][UPSEID:0x1] sess deleted
2024-02-19T17:32:57.304152989+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1610612737 period:0}]
2024-02-19T17:32:57.304598620+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1073741829 period:0}]
2024-02-19T17:32:57.305273023+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1073741825 period:0}]
2024-02-19T17:32:57.307922154+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114114] send rsp
2024-02-19T17:32:58.364335401+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179649] start timer(4s)
2024-02-19T17:32:58.364423937+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179649] recv req - rxTrFound(false)
2024-02-19T17:32:58.364476911+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleSessionEstablishmentRequest
2024-02-19T17:32:58.364559560+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] remote nodeid: 10.246.112.62
2024-02-19T17:32:58.364603822+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] fseid.SEID: 0x11120
2024-02-19T17:32:58.364635885+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62][CPSEID:0x11120][UPSEID:0x1] New session
2024-02-19T17:32:58.367866396+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179649] send rsp
2024-02-19T17:32:58.585525722+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179650] start timer(4s)
2024-02-19T17:32:58.585663707+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179650] recv req - rxTrFound(false)
2024-02-19T17:32:58.585726069+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleSessionDeletionRequest
2024-02-19T17:32:58.585764617+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62][CPSEID:0x11120][UPSEID:0x1] sess deleted
2024-02-19T17:32:58.587359400+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1610612737 period:0}]
2024-02-19T17:32:58.588589969+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1073741829 period:0}]
2024-02-19T17:32:58.588987051+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1073741825 period:0}]
2024-02-19T17:32:58.591060454+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179650] send rsp
2024-02-19T17:32:59.484242837+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1245185] start timer(4s)
2024-02-19T17:32:59.484876222+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1245185] recv req - rxTrFound(false)
2024-02-19T17:32:59.485008246+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleSessionEstablishmentRequest
2024-02-19T17:32:59.485056095+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] remote nodeid: 10.246.112.62
2024-02-19T17:32:59.485085008+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805] fseid.SEID: 0x11130
2024-02-19T17:32:59.485137667+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62][CPSEID:0x11130][UPSEID:0x1] New session
2024-02-19T17:32:59.490618546+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1245185] send rsp
2024-02-19T17:32:59.683589588+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1245186] start timer(4s)
2024-02-19T17:32:59.683741134+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1245186] recv req - rxTrFound(false)
2024-02-19T17:32:59.683783204+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleSessionDeletionRequest
2024-02-19T17:32:59.683815278+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805][CPNodeID:10.246.112.62][CPSEID:0x11130][UPSEID:0x1] sess deleted
2024-02-19T17:32:59.685054442+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1073741829 period:0}]
2024-02-19T17:32:59.685458844+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1073741825 period:0}]
2024-02-19T17:32:59.690346421+08:00 [INFO][UPF][Perio] recv event[TYPE_PERIO_DEL][{eType:2 lSeid:1 urrid:1610612737 period:0}]
2024-02-19T17:32:59.692954573+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1245186] send rsp
2024-02-19T17:33:01.055317059+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114113] timeout, delete rxtr
2024-02-19T17:33:01.303174104+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1114114] timeout, delete rxtr
2024-02-19T17:33:01.722778344+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] start timer(4s)
2024-02-19T17:33:01.723347109+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] recv req - rxTrFound(false)
2024-02-19T17:33:01.723382852+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] handleHeartbeatRequest
2024-02-19T17:33:01.723401847+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-0] send rsp
2024-02-19T17:33:02.366022592+08:00 [DEBU][UPF][PFCP][LAddr:192.168.99.22:8805][RXTR:10.246.112.62:8805-1179649] timeout, delete rxtr
^C2024-02-19T17:33:02.510749519+08:00 [INFO][UPF][Main] Shutdown UPF ...
2024-02-19T17:33:02.510915361+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] Stopping pfcp server
2024-02-19T17:33:02.511194501+08:00 [ERRO][UPF][PFCP][LAddr:192.168.99.22:8805] read udp4 192.168.99.22:8805: use of closed network connection
2024-02-19T17:33:02.512772922+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] pfcp reciver stopped
2024-02-19T17:33:02.512854551+08:00 [INFO][UPF][PFCP][LAddr:192.168.99.22:8805] pfcp server stopped
2024-02-19T17:33:02.557913268+08:00 [INFO][UPF][Perio] recv event[TYPE_SERVER_CLOSE][{eType:4 lSeid:0 urrid:0 period:0}]
2024-02-19T17:33:02.558040600+08:00 [INFO][UPF][Perio] perio server stopped
2024-02-19T17:33:02.558359526+08:00 [INFO][UPF][Main] Terminating UPF...
2024-02-19T17:33:02.558407547+08:00 [INFO][UPF][Main] UPF terminated
2024-02-19T17:33:02.558504364+08:00 [INFO][UPF][Main] UPF exited

Configs

UPF

version: 1.0.3
description: UPF initial local configuration

# The listen IP and nodeID of the N4 interface on this UPF (Can't set to 0.0.0.0)
pfcp:
  addr: 192.168.99.22   # IP addr for listening
  nodeID: 192.168.99.22 # External IP or FQDN can be reached
  retransTimeout: 1s # retransmission timeout
  maxRetrans: 3 # the max number of retransmission

gtpu:
  forwarder: gtp5g
  # The IP list of the N3/N9 interfaces on this UPF
  # If there are multiple connection, set addr to 0.0.0.0 or list all the addresses
  ifList:
    - addr: 192.168.99.22
      type: N3
      name: n3-realm
      # ifname: gtpif
      # mtu: 1400

# The DNN list supported by UPF
dnnList:
  - dnn: [REDACTED] # Data Network Name
    cidr: 10.246.115.240/29 # Classless Inter-Domain Routing for assigned IPv4 pool of UE
    # natifname: eth0

logger: # log output setting
  enable: true # true or false
  level: debug # how detailed to output, value: trace, debug, info, warn, error, fatal, panic
  reportCaller: false # enable the caller report or not, value: true or false

UE

# IMSI number of the UE. IMSI = [MCC|MNC|MSISDN] (In total 15 digits)
supi: 'imsi-001019000000007'
# Mobile Country Code value of HPLMN
mcc: '001'
# Mobile Network Code value of HPLMN (2 or 3 digits)
mnc: '01'
# SUCI Protection Scheme : 0 for Null-scheme, 1 for Profile A and 2 for Profile B
protectionScheme: 0
# Home Network Public Key for protecting with SUCI Profile A
homeNetworkPublicKey: '5a8d38864820197c3394b92613b20b91633cbd897119273bf8e4a6f4eec0a650'
# Home Network Public Key ID for protecting with SUCI Profile A
homeNetworkPublicKeyId: 1
# Routing Indicator
routingIndicator: '0000'

# Permanent subscription key
key: '2E56EE784C17E0A644CC95E39B7EBD71'
# Operator code (OP or OPC) of the UE
op: 'B36388CCA4AC6FD87866CFAAC2B613FE'
# This value specifies the OP type and it can be either 'OP' or 'OPC'
opType: 'OPC'
# Authentication Management Field (AMF) value
amf: '8000'
# IMEI number of the device. It is used if no SUPI is provided
imei: '356938035643803'
# IMEISV number of the device. It is used if no SUPI and IMEI is provided
imeiSv: '4370816125816151'

# List of gNB IP addresses for Radio Link Simulation
gnbSearchList:
  - 127.0.0.1

# UAC Access Identities Configuration
uacAic:
  mps: false
  mcs: false

# UAC Access Control Class
uacAcc:
  normalClass: 0
  class11: false
  class12: false
  class13: false
  class14: false
  class15: false

# Initial PDU sessions to be established
sessions:
  - type: 'IPv4'
    apn: '[REDACTED]'
    slice:
      sst: 1
      sd: 1

# Configured NSSAI for this UE by HPLMN
configured-nssai:
  - sst: 1
    sd: 1

# Default Configured NSSAI for this UE
default-nssai:
  - sst: 1
    sd: 1

# Supported integrity algorithms by this UE
integrity:
  IA1: true
  IA2: true
  IA3: true

# Supported encryption algorithms by this UE
ciphering:
  EA1: true
  EA2: true
  EA3: true

# Integrity protection maximum data rate for user plane
integrityMaxRate:
  uplink: 'full'
  downlink: 'full'

RAN

mcc: '001'          # Mobile Country Code value
mnc: '01'           # Mobile Network Code value (2 or 3 digits)

nci: '[REDACTED]'  # NR Cell Identity (36-bit)
idLength: 32       # NR gNB ID length in bits [22...32]
tac: [REDACTED]              # Tracking Area Code

linkIp: 127.0.0.1   # gNB's local IP address for Radio Link Simulation (Usually same with local IP)
ngapIp: 192.168.99.11   # gNB's local IP address for N2 Interface (Usually same with local IP)
gtpIp: 192.168.99.11   # gNB's local IP address for N3 Interface (Usually same with local IP)

# List of AMF address information
amfConfigs:
  - address: 10.246.112.18
    port: 38412

# List of supported S-NSSAIs by this gNB
slices:
  - sst: 1
    sd: 1

# Indicates whether or not SCTP stream number errors should be ignored.
ignoreStreamIds: true

Observations

From UE logs, the error “PDU Session Establishment Reject received [REACTIVATION_REQUESTED]” suggests that a PDU session failed to establish, with cause given as
“REACTIVATION_REQUESTED”. According to 3GPP 24.501, this 5GSM cause is used by the network to request a PDU session reactivation, which may suggest that the problem is not due to UE/RAN misconfiguration, but rather due to other NFs within the 5GC.

From RAN logs, it seems the RAN is not receiving Uplink TNL information for the creation of a GTP tunnel, so it is returning the error “PDU session resource could not setup: Uplink TNL information is missing”, and thus the PDU session fails to be established.

Examining the UERANSIM_to_CMU pcap file, we can see at AMF->RAN, in the packet containing “PDUSessionResourceSetupRequest”, a gTP-TEID of 00000000 is provided to RAN by the AMF, according to NGAP>NGAP-PDU: initiatingMessage>initiatingMessage>value>PDUSessionResourceSetupRequest>protocolIEs>Item 2>ProtocolIE-Field>value>PDUSessionResourceSetupListSUReq>Item 0>PDUSessionResourceSetupItemSUReq>pDUSessionResourceSetupRequestTransfer>Item 1>ProtocolIE-Field>value>UPTransportLayerInformation>gTPTunnel

NullTeid_2
NullTeid_21265×688 32.4 KB

I speculate this could be the reason why RAN is reporting TNL information missing, as a gTP-TEID of 00000000 seems unusual. Also, no transportLayerAddress information is being provided either. I think this suggests something wrong with TEID allocation happening at the SMF.

Examining the UPF_to_CMU pcap file, in the packet “PFCP Session Establishment Request” it appears the UPF is being told to choose the F-TEID by SMF, according to PFCP>Create PDR: PDR ID: 18944>PDI>F-TEID

ChooseTeid_2
ChooseTeid_21004×740 19.5 KB

In “PFCP Session Establishment Response”, the UPF is not reporting the creation of Traffic Endpoints.
Perhaps this is the reason why no TEID info is provided to RAN?

NoCreateTunnel_2
NoCreateTunnel_21003×542 20.3 KB

I apologize if any incorrect assumptions were made regarding the PDU/PFCP establishment procedures. I have tried my best to understand the 3GPP documents. Any corrections or input regarding my assumptions is welcomed.

Additionally, any help or ideas would be greatly appreciated.

Best regards,
Howard

#2

Hi @howardswe499
Could you please provide the pcap file?
I noticed that SMF sends the PFCP Session Deletion after the PFCP Session created, It’s not a expected behavior during PDU Session Establishment procedure.

Thanks.

#3

Hi Ian,
I’ve sent a message to you.

Also, I have found another open source UPF that allows for successful PDU session establishment with Nokia SMF. It’s called eUPF (GitHub - edgecomllc/eupf: 5G User Plane Function (UPF) based on eBPF). However, this UPF isn’t perfect for us as I’ve run into problems with connection to DN. However, I think it still may be useful for reference.

The main difference I noticed was that eUPF supported user plane functions UEIP and FTUP in PFCP Association Setup Response, which means that it had the function to tell SMF what TEID it was going to use when asked.

eUPF_Pfcp_Uplane_Fxns
eUPF_Pfcp_Uplane_Fxns967×855 14.8 KB

And so it was able to reply to SMF when told to choose TEID, which in turn let RAN receive TNL information.

eUPF_Choose_Teid
eUPF_Choose_Teid1004×584 15.9 KB

eUPF_Teid_Chosen
eUPF_Teid_Chosen1003×717 29.5 KB

eUPF_TNL_Teid
eUPF_TNL_Teid1576×767 34.1 KB

Which lead to successful PDU Session Establishment.

Hope this helps.

Howard

#4

I found synch failure between AMF and RAN. I suspect that AMF and SMF on CMU have not completed the NRF registration process, so they cannot find PCF and AUSF, which leads to authentication failure.
Please provide us with the config files and log files for SMF(on CMU), AMF(on CMU), and other NFs.
Thanks.

#5

Hi Ian,

Unfortunately, it is not convenient for me to share config of CMU. However, I’ve passed on your request to senior engineers and they informed me that Nokia CMU doesn’t have NRF function, the NFs are connected via hard-coding their UUID. See the image below that describes CMU functionalities:
image
As you can see, only UPF, SMF, AMF, AUSF, UDM are available for 5G.

They also told me that occasionally Synch failures occur, but it does not affect normal operation.

Best Regards
Howard

#6

Hi Howard,
I observed that the SMF sends an association release before sending an association create in the UPF log. This behavior does not seem to be the same as the flow currently used by free5gc, which also does not currently provide an association release function.
I believe that the multiple PDU session establishment procedures are initiated because the UPF → SMF response does not match the SMF IEs you are using, causing the SMF to initiate a session deletion procedure. We are currently verifying whether the e-UPF in the context you mentioned responds differently to the free5gc implementation when responding to the SMF session request response.

#7

Hi Ian, thanks for your reply.

Yes, the reason why SMF sent Association Release in the beginning was so that I could initiate the Association process from CMU-side by restarting the service on CMU; as far as I’m aware no open source UPFs support UPF-initiated association requests yet. (Maybe this could be a future feature?) I had to do this in order to get the SMF & UPF associated so the CMU selects F5GC-UPF when UE connects.

A major problem I noticed was that RAN did not receive a TEID+N3 endpoint address in the PDUSessionResourceSetupRequest from AMF. Hence I suspect the problem was related to TEID allocation. And checking the Session Establishment Response from F5GC-UPF revealed that no TEIDs were replied to SMF. The deletion request was due to the above problems causing a failure in PDU Session Establishment, I think.

In eUPF, the RAN received the correct information from AMF (as shown in my previous reply), so I don’t think it’s due to configuration problem on CMU-side.

BR
Howard

#8

Hi, Howard
Thank you for your suggestion. We have included "UPF initialted Association " in our future plan.

#9

Hi Ian,

Regarding UPF-triggered SMF Association Setup Requests, here is a discussion I had with the creator of eUPF (Trigger PFCP Assoc. Setup Request from SMF When Receiving Sess. Est. Request from Unassociated SMF · edgecomllc/eupf · Discussion #540 · GitHub) on a similar problem.

In short, eUPF on branch 539 is able to force CMU SMF to re-send a PFCP Association Request if they receive a PFCP Session Establishment Request from an un-associated SMF. This lets the UPF agree to become selected for PDU when requested by SMF (previously, UPF would reject establishment request, and no other actions would be taken). They did it by adding Node-ID field to UPF’s Session Establishment Response; this change also makes it 3GPP-Compliant. This is different to UPF-initiated PFCP Association, as far as I’m aware, but it seems to be a quick fix that achieves a similar outcome.

Hope you guys can implement this feature in the future! Also, best of luck on the FTUP fix.

Best regards
Howard

#10

Hi,
since there haven’t any replies from you, the admin decides to close this topic.
If you have any further questions about this topic, please message the admin or create another topic.
Thanks!

Admin

#11