niloysh / free5gc-k8s

5G core deployment using Free5GC
MIT License
11 stars 1 forks source link

UE2 wont connect properly #1

Open jayson-dex opened 8 months ago

jayson-dex commented 8 months ago

Hello,

I am having problems connecting the 2nd UE. In my opinion I have transferred the subcriber info correctly in the webui and the UE is also shown as connected, but according to the logs this does not seem to be the case.

For example, the AMF has the following errors:

2024-02-11T09:33:27Z [INFO][AMF][Producer] [OAM] Handle Registered UE Context
2024-02-11T09:33:27Z [INFO][AMF][GIN] | 200 |     10.244.0.95 | GET     | /namf-oam/v1/registered-ue-context |
2024-02-11T09:33:39Z [INFO][AMF][NGAP][10.10.2.22:45029][AMF_UE_NGAP_ID:2] Uplink NAS Transport (RAN UE NGAP ID: 2)
2024-02-11T09:33:39Z [INFO][LIB][FSM] Handle event[Gmm Message], transition from [Registered] to [Registered]
2024-02-11T09:33:39Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-001010000000002] Handle UL NAS Transport
2024-02-11T09:33:39Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-001010000000002] Transport 5GSM Message to SMF
2024-02-11T09:33:39Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-001010000000002] Select SMF [snssai: {Sst:1 Sd:000002}, dnn: streaming]
2024-02-11T09:33:39Z [WARN][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-001010000000002] nsiInformation is still nil, use default NRF[http://nrf-nnrf:8000]
2024-02-11T09:33:39Z [ERRO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-001010000000002] CreateSmContextRequest Error: undefined response type

The UE itself shows the following:

[2024-02-11 09:33:22.719] [nas] [info] UE switches to state [MM-DEREGISTERED/PLMN-SEARCH]
[2024-02-11 09:33:22.720] [rrc] [debug] New signal detected for cell[1], total [1] cells in coverage
[2024-02-11 09:33:22.720] [nas] [info] Selected plmn[001/01]
[2024-02-11 09:33:22.720] [rrc] [info] Selected cell plmn[001/01] tac[1] category[SUITABLE]
[2024-02-11 09:33:22.720] [nas] [info] UE switches to state [MM-DEREGISTERED/PS]
[2024-02-11 09:33:22.720] [nas] [info] UE switches to state [MM-DEREGISTERED/NORMAL-SERVICE]
[2024-02-11 09:33:22.720] [nas] [debug] Initial registration required due to [MM-DEREG-NORMAL-SERVICE]
[2024-02-11 09:33:22.720] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-11 09:33:22.720] [nas] [debug] Sending Initial Registration
[2024-02-11 09:33:22.720] [nas] [info] UE switches to state [MM-REGISTER-INITIATED]
[2024-02-11 09:33:22.720] [rrc] [debug] Sending RRC Setup Request
[2024-02-11 09:33:22.720] [rrc] [info] RRC connection established
[2024-02-11 09:33:22.720] [rrc] [info] UE switches to state [RRC-CONNECTED]
[2024-02-11 09:33:22.720] [nas] [info] UE switches to state [CM-CONNECTED]
[2024-02-11 09:33:22.731] [nas] [debug] Authentication Request received
[2024-02-11 09:33:22.735] [nas] [debug] Security Mode Command received
[2024-02-11 09:33:22.735] [nas] [debug] Selected integrity[2] ciphering[0]
[2024-02-11 09:33:22.757] [nas] [debug] Registration accept received
[2024-02-11 09:33:22.757] [nas] [info] UE switches to state [MM-REGISTERED/NORMAL-SERVICE]
[2024-02-11 09:33:22.757] [nas] [debug] Sending Registration Complete
[2024-02-11 09:33:22.757] [nas] [info] Initial Registration is successful
[2024-02-11 09:33:22.757] [nas] [debug] Sending PDU Session Establishment Request
[2024-02-11 09:33:22.757] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-11 09:33:22.978] [nas] [error] PDU Session Establishment Reject received [REQUEST_REJECTED_UNSPECIFIED]
[2024-02-11 09:33:22.978] [nas] [error] Received PTI [0] value is invalid
[2024-02-11 09:33:22.978] [nas] [warning] Sending SM Cause[INVALID_PTI_VALUE] for PSI[1]
[2024-02-11 09:33:22.979] [nas] [error] MM Cause with invalid SM message type in DL NAS Transport, ignoring received message
[2024-02-11 09:33:39.743] [nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry
[2024-02-11 09:33:39.743] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-11 09:33:55.760] [nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry
[2024-02-11 09:33:55.760] [nas] [debug] UAC access attempt is allowed for identity[0], category[MO_sig]
[2024-02-11 09:34:11.779] [nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry

As I said, the UE is shown as connected in the webui, but when you click on "Show info" the page enters a loading state because the amf cannot load the UE correctly. Do you have any idea how this could be fixed?

Thanks in advance Best regards Justin

niloysh commented 8 months ago

In the default configuration, UE2 is connected to slice2 (SST: 1, SD: 000002), which uses SMF2 and UPF2. Please check the logs of these two NFs.

jayson-dex commented 8 months ago

SMF2 shows the following:

2024-02-12T15:30:32Z [INFO][SMF][CTX] Selected UPF: UPF2
2024-02-12T15:30:32Z [INFO][SMF][PduSess] UE[imsi-001010000000002] PDUSessionID[1] IP[10.2.0.1]
2024-02-12T15:30:32Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest
2024-02-12T15:30:32Z [ERRO][SMF][CTX] this SMContext[urn:uuid:446d977b-3fb4-4d0d-b43f-ed3e69a52cd7] has no subscription pdu session type info
2024-02-12T15:30:32Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-001010000000002] PDUSessionID[1]
2024-02-12T15:30:32Z [ERRO][SMF][PduSess] setup sm policy association failed: 400 Bad Request {  400 Can't find UE SM Policy Data in UDR  USER_UNKNOWN []}
2024-02-12T15:30:32Z [INFO][SMF][GIN] | 403 |    10.244.0.115 | POST    | /nsmf-pdusession/v1/sm-contexts |
2024-02-12T15:30:48Z [INFO][SMF][PduSess] Receive Create SM Context Request
2024-02-12T15:30:48Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate
2024-02-12T15:30:48Z [ERRO][SMF][GIN] panic: runtime error: invalid memory address or nil pointer dereference
goroutine 76 [running]:
runtime/debug.Stack(0xc00037c7b0, 0xc7d480, 0x150b7b0)
        /usr/local/go/src/runtime/debug/stack.go:24 +0x9d
github.com/free5gc/util/logger.ginRecover.func1.1(0xc0003de690, 0xc00016a200)
        /go/pkg/mod/github.com/free5gc/util@v1.0.3/logger/logger.go:212 +0x27a
panic(0xc7d480, 0x150b7b0)
        /usr/local/go/src/runtime/panic.go:969 +0x166
github.com/free5gc/smf/internal/sbi/producer.ReleaseTunnel(0xc000020c00, 0xc39f20, 0x1, 0xc0000b0960)
        /go/src/free5gc/NFs/smf/internal/sbi/producer/datapath.go:287 +0xc9
github.com/free5gc/smf/internal/sbi/producer.releaseSession(0xc000020c00, 0x6)
        /go/src/free5gc/NFs/smf/internal/sbi/producer/pdu_session.go:1045 +0x36
github.com/free5gc/smf/internal/sbi/producer.HandlePDUSessionSMContextLocalRelease(0xc000020c00, 0xc00058ed80)
        /go/src/free5gc/NFs/smf/internal/sbi/producer/pdu_session.go:1006 +0x151
github.com/free5gc/smf/internal/sbi/producer.HandlePDUSessionSMContextCreate(0xc00058ed80, 0xc0005a6800, 0x15, 0x3e8, 0x0)
        /go/src/free5gc/NFs/smf/internal/sbi/producer/pdu_session.go:52 +0x3163
github.com/free5gc/smf/internal/sbi/pdusession.HTTPPostSmContexts(0xc00016a200)
        /go/src/free5gc/NFs/smf/internal/sbi/pdusession/api_sm_contexts_collection.go:54 +0x295
github.com/gin-gonic/gin.(*Context).Next(0xc00016a200)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.7.3/context.go:165 +0x3b
github.com/free5gc/util/logger.ginRecover.func1(0xc00016a200)
        /go/pkg/mod/github.com/free5gc/util@v1.0.3/logger/logger.go:244 +0x60
github.com/gin-gonic/gin.(*Context).Next(0xc00016a200)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.7.3/context.go:165 +0x3b
github.com/free5gc/util/logger.ginToLogrus.func1(0xc00016a200)
        /go/pkg/mod/github.com/free5gc/util@v1.0.3/logger/logger.go:179 +0x7e
github.com/gin-gonic/gin.(*Context).Next(0xc00016a200)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.7.3/context.go:165 +0x3b
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc0000d4000, 0xc00016a200)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.7.3/gin.go:489 +0x60d
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc0000d4000, 0xefa7c0, 0xc00000e0b8, 0xc00026a900)
        /go/pkg/mod/github.com/gin-gonic/gin@v1.7.3/gin.go:445 +0x15c
golang.org/x/net/http2.(*serverConn).runHandler(0xc000239200, 0xc00000e0b8, 0xc00026a900, 0xc000408120)
        /go/pkg/mod/golang.org/x/net@v0.0.0-20210805182204-aaa1db679c0d/http2/server.go:2158 +0x8b
created by golang.org/x/net/http2.(*serverConn).processHeaders
        /go/pkg/mod/golang.org/x/net@v0.0.0-20210805182204-aaa1db679c0d/http2/server.go:1888 +0x4db
2024-02-12T15:30:48Z [INFO][SMF][GIN] | 500 |    10.244.0.115 | POST    | /nsmf-pdusession/v1/sm-contexts

And UPF2 shows the following:

2024-02-12T15:29:08Z [INFO][UPF][Main] UPF version:
        free5GC version: v3.2.0
        build time:      2022-09-24T15:06:48Z
        commit hash:     4972fffb
        commit time:     2022-06-29T05:46:33Z
        go version:      go1.14.4 linux/amd64
2024-02-12T15:29:08Z [INFO][UPF][Cfg] Read config from [/free5gc/config/upfcfg.yaml]
2024-02-12T15:29:08Z [INFO][UPF][Cfg] ==================================================
2024-02-12T15:29:08Z [INFO][UPF][Cfg] (*factory.Config)(0xc0003174f0)({
        Version: (string) (len=5) "1.0.3",
        Description: (string) (len=31) "UPF initial local configuration",
        Pfcp: (*factory.Pfcp)(0xc0004571a0)({
                Addr: (string) (len=9) "10.10.4.2",
                NodeID: (string) (len=9) "10.10.4.2",
                RetransTimeout: (time.Duration) 1s,
                MaxRetrans: (uint8) 3
        }),
        Gtpu: (*factory.Gtpu)(0xc000457350)({
                Forwarder: (string) (len=5) "gtp5g",
                IfList: ([]factory.IfInfo) (len=1 cap=1) {
                        (factory.IfInfo) {
                                Addr: (string) (len=9) "10.10.3.2",
                                Type: (string) (len=2) "N3",
                                Name: (string) "",
                                IfName: (string) (len=7) "upf2gtp"
                        }
                }
        }),
        DnnList: ([]factory.DnnList) (len=1 cap=1) {
                (factory.DnnList) {
                        Dnn: (string) (len=9) "streaming",
                        Cidr: (string) (len=11) "10.2.0.0/16",
                        NatIfName: (string) ""
                }
        },
        Logger: (*factory.Logger)(0xc000448b60)({
                Enable: (bool) true,
                Level: (string) (len=4) "info",
                ReportCaller: (bool) false
        })
})
2024-02-12T15:29:08Z [INFO][UPF][Cfg] ==================================================
2024-02-12T15:29:08Z [INFO][UPF][Main] Log level is set to [info] level
2024-02-12T15:29:08Z [INFO][UPF][Main] starting Gtpu Forwarder [gtp5g]
2024-02-12T15:29:08Z [INFO][UPF][Main] GTP Address: "10.10.3.2:2152"
2024-02-12T15:29:08Z [INFO][UPF][Buff] buff server started
2024-02-12T15:29:08Z [INFO][UPF][Pfcp][10.10.4.2:8805] starting pfcp server
2024-02-12T15:29:08Z [INFO][UPF][Pfcp][10.10.4.2:8805] pfcp server started
2024-02-12T15:29:08Z [INFO][UPF][Main] UPF started
2024-02-12T15:29:12Z [INFO][UPF][Pfcp][10.10.4.2:8805] handleAssociationSetupRequest
2024-02-12T15:29:12Z [INFO][UPF][Pfcp][10.10.4.2:8805][rNodeID:10.10.4.102] New node

I think at this point I lack the understanding to find out what could lead to this.

niloysh commented 8 months ago

The issue appears to be related to NSI. However, I cannot recreate the issue on my end. Try clearing MongoDB information related to NSI and start fresh.

You can bring up the mongo shell as follows.

./k8s-shell.sh mongodb free5gc
# mongo
jayson-dex commented 8 months ago

Unfortunately, that didn't work either. We even tried to drop the entire table with db.dropDatabase(). We use a fresh VM and only install the tools from the setup. Maybe something is missing on the system? I found a similar issue where it is suggested to update the free5GC version. Do you think this could work?