Error running Free5GC with Test Generator

dlake02 · December 30, 2020, 3:40am

Hello

I have built and configured Free5GC to run with CP on 10.5.23.30 and UPF on 10.5.23.20 (SBI addresses).

The AMF is on 10.0.50.1 and the gNB is 10.0.50.2. gNB and UE are emulated by Spirent Landslide.

My trace for CP is attached.

My trace from gNB to AMF is also attached. I see NGSetupRequest but the AMF never replies.

Can someone help please?

I tried to upload amfcfg.cong and smfcfg.conf but I’m not allowed to load more than 2 trace files

Trace 1.pcap (1.4 KB) Log1.txt (126.4 KB)
Thanks

David

jay16213 · December 30, 2020, 3:40am

I found there are some NFs register to NRF error (connection refused),
maybe you did not run NRF first? In free5gc, NRF should run before any other NFs otherwise there may cause some unexpected error

dlake02 · December 30, 2020, 3:40am

OK - I’ve changed so that all the NFs are listening on the public IP address 10.5.23.30.

Trace 2 shows the startup of the functions with “Trace” enabled.

When I try and register I get no response from the AMF.

Trace 2.pcap (1.4 KB) Trace2.txt (81.6 KB)

I don’t know where to start looking.

The CP elements are on 10.5.23.30. The UPF is on 10.5.23.28.

David

dcrowley · December 30, 2020, 3:40am

Dave,

2 areas I would check as its not immediately, at least to me why your not getting a response, maybe this would help?

1.) Run an “strace -p” both on both NF’s so you can see at a lower layer if there are errors you could next act on

2.) When you run the test go scripts for registration where does that log difer from your output.

If you don’t have the test scripts o/p let me know and I will send you what I have

Hope this helps a little

Donal

dcrowley · December 30, 2020, 3:40am

Dave,

Another possibility is we can set some breakpoints in the AMF Go Code and run it against a debugger. Once you run your call flow, we can see exactly whats going on in the AMF.

Hope this helps

Donal

dlake02 · December 30, 2020, 3:40am

I’m trying to post back but the Forum won’t let me! d DOT lake AT surrey DOT ac DOT uk.

I’m not sure why I’m not allowed to post - the forum is telling me to wait 6 hours!!!

With strace running on the AMF, I see this immedately after the NGSetupRequest and the AMF just hangs:

futex(0x16cb420, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=999956107}DEBU[2020-08-04T23:21:20+01:00]/home/admin5g/go/src/free5gc/lib/ngap/ngapSctp/sctp.go:105 free5gc/lib/ngap/ngapSctp.Accept() Accepted Connection from RemoteAddr: 10.0.50.2:38412 NGAP=NGAP
DEBU[2020-08-04T23:21:20+01:00]/home/admin5g/go/src/free5gc/lib/ngap/ngapSctp/sctp.go:109 free5gc/lib/ngap/ngapSctp.Accept() A new Connection 1. NGAP=NGAP
INFO[2020-08-04T23:21:20+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/sctp/sctp.go:42 free5gc/src/amf/ngap/sctp.Server.func1() [AMF] NGAP SCTP Accept from: 10.0.50.2:38412 AMF=NGAP
) = -1 ETIMEDOUT (Connection timed out)
clock_gettime(CLOCK_MONOTONIC, {tv_sec=28728, tv_nsec=660784287}) = 0
futex(0x16c7348, FUTEX_WAIT_PRIVATE, 0, NULL

Then after about 5 minutes I see this:

root@Free5GC-CP:~/free5gc# DEBU[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/lib/ngap/ngapSctp/sctp.go:134 free5gc/lib/ngap/ngapSctp.Start() Read: 10.0.50.2:38412, 8 PR@
                                                                                                                                                                                   0.free5gc@@, 00150038000004001b00090002083950000000000052400b0400302e6672656535676300660010000000000100020839000010080102030015400140  NGAP=NGAP
DEBU[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/lib/ngap/ngapSctp/sctp.go:127 free5gc/lib/ngap/ngapSctp.Start() Error EOF                                     NGAP=NGAP
DEBU[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/lib/ngap/ngapSctp/sctp.go:158 free5gc/lib/ngap/ngapSctp.closeConnection() Now, 0 connections is alive.                  NGAP=NGAP
DEBU[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/sctp/sctp.go:100 free5gc/src/amf/ngap/sctp.(*SCTPListener).forwardData() Packet get: 0x00150038000004001b00090002083950000000000052400b0400302e6672656535676300660010000000000100020839000010080102030015400140  AMF=NGAP
INFO[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:50 free5gc/src/amf/ngap.HandleNGSetupRequest() [AMF] NG Setup request                        AMF=NGAP
TRAC[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:56 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE GlobalRANNodeID              AMF=NGAP
TRAC[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:70 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE RANNodeName                  AMF=NGAP
TRAC[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:63 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE SupportedTAList              AMF=NGAP
TRAC[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:77 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE DefaultPagingDRX             AMF=NGAP
TRAC[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:90 free5gc/src/amf/ngap.HandleNGSetupRequest() PagingDRX[2]                                  AMF=NGAP
TRAC[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:112 free5gc/src/amf/ngap.HandleNGSetupRequest() PLMN_ID[MCC:208 MNC:093] TAC[000001]          AMF=NGAP
WARN[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:139 free5gc/src/amf/ngap.HandleNGSetupRequest() NG-Setup failure: Cannot find Served TAI in AMF  AMF=NGAP
INFO[2020-08-04T23:27:43+01:00]/home/admin5g/go/src/free5gc/src/amf/ngap/message/send.go:91 free5gc/src/amf/ngap/message.SendNGSetupFailure() [AMF] Send NG-Setup failure                   AMF=NGAP
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0xb5a779]

goroutine 11 [running]:
free5gc/src/amf/ngap/message.SendToRan(0xc0000868c0, 0xc0007fdde0, 0xc, 0x10)
        /home/admin5g/go/src/free5gc/src/amf/ngap/message/send.go:32 +0x79
free5gc/src/amf/ngap/message.SendNGSetupFailure(0xc0000868c0, 0x5, 0x0, 0x0, 0x0, 0x0, 0xc0007fd308, 0x0)
        /home/admin5g/go/src/free5gc/src/amf/ngap/message/send.go:103 +0x1b4
free5gc/src/amf/ngap.HandleNGSetupRequest(0xc0000868c0, 0xc000789e20)
        /home/admin5g/go/src/free5gc/src/amf/ngap/handler.go:150 +0xf9c
free5gc/src/amf/ngap.Dispatch(0xc00078e9f0, 0xf, 0xc0007d8000, 0x3c, 0x2000)
        /home/admin5g/go/src/free5gc/src/amf/ngap/dispatcher.go:37 +0x3c2
free5gc/src/amf/handler.Handle()
        /home/admin5g/go/src/free5gc/src/amf/handler/handler.go:36 +0x1ec
created by free5gc/src/amf/service.(*AMF).Start
        /home/admin5g/go/src/free5gc/src/amf/service/amf_init.go:145 +0x4a9

David

jay16213 · December 30, 2020, 3:40am

According to your information, I think your environment may have some sctp connection issue: you can see at AMF side, it reads EOF from client(your GNB) and the connection is closed after this event.

Second, from your pcap file I found plmnID field at 2 IEs in NGSetupRequest may has error:
GlobalGNB-ID and SupportTAList.

The PLMN ID should be 208-93 (the default plmn if you didn’t change the config of AMF), not 208-093, these two values are different. for 2-digit mnc, you should fill 02 f8 39, not 02 08 39 in your packet. This is why AMF report an error that Cannot find Served TAI in AMF then send NG-Setup failure

On the other hand, free5gc can output the log file automatically, please upload the log file from path <your_path>/free5gc/log/free5gc.log and <your_path>free5gc/log/nf/amf.log with AMF log level set to trace

dlake02 · December 30, 2020, 3:40am

Reinstalled with updated Go and seem to be getting further.

I’m getting a panic error now which crashes the AMF:

root@Free5GC-CP:~/free5gc# INFO[2020-08-05T16:08:45+01:00]/src/amf/ngap/sctp/sctp.go:42 free5gc/src/amf/ngap/sctp.Server.func1() [AMF] NGAP SCTP Accept from: 10.0.50.2:9487   AMF=NGAP
DEBU[2020-08-05T16:08:48+01:00]/src/amf/ngap/sctp/sctp.go:100 free5gc/src/amf/ngap/sctp.(*SCTPListener).forwardData() Packet get: 0x00150029000003001b00090002f83950000000000066001000000000010002f839000010080102030015400140  AMF=NGAP
INFO[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:49 free5gc/src/amf/ngap.HandleNGSetupRequest() [AMF] NG Setup request                        AMF=NGAP
TRAC[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:55 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE GlobalRANNodeID              AMF=NGAP
TRAC[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:62 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE SupportedTAList              AMF=NGAP
TRAC[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:76 free5gc/src/amf/ngap.HandleNGSetupRequest() [NGAP] Decode IE DefaultPagingDRX             AMF=NGAP
TRAC[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:89 free5gc/src/amf/ngap.HandleNGSetupRequest() PagingDRX[2]                                  AMF=NGAP
TRAC[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:111 free5gc/src/amf/ngap.HandleNGSetupRequest() PLMN_ID[MCC:208 MNC:93] TAC[000001]           AMF=NGAP
TRAC[2020-08-05T16:08:48+01:00]/src/amf/ngap/handler.go:132 free5gc/src/amf/ngap.HandleNGSetupRequest() SERVED_TAI_INDEX[0]                           AMF=NGAP
INFO[2020-08-05T16:08:48+01:00]/src/amf/ngap/message/send.go:79 free5gc/src/amf/ngap/message.SendNGSetupResponse() [AMF] Send NG-Setup response                  AMF=NGAP
DEBU[2020-08-05T16:08:48+01:00]/src/amf/ngap/message/send.go:32 free5gc/src/amf/ngap/message.SendToRan() [NGAP] Send To Ran [IP: 10.0.50.2:9487]       AMF=NGAP
DEBU[2020-08-05T16:08:50+01:00]/src/amf/ngap/sctp/sctp.go:100 free5gc/src/amf/ngap/sctp.(*SCTPListener).forwardData() Packet get: 0x000f404200000500550002000000260018177e004179000d01020839f0ff000000000000f32e02f0f00079000f4002f839000000001002f839000001005a4001180070400100  AMF=NGAP
INFO[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:882 free5gc/src/amf/ngap.HandleInitialUEMessage() [AMF] Initial UE Message                      AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:888 free5gc/src/amf/ngap.HandleInitialUEMessage() [NGAP] Decode IE RanUeNgapID                  AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:896 free5gc/src/amf/ngap.HandleInitialUEMessage() [NGAP] Decode IE NasPdu                       AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:904 free5gc/src/amf/ngap.HandleInitialUEMessage() [NGAP] Decode IE UserLocationInformation      AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:912 free5gc/src/amf/ngap.HandleInitialUEMessage() [NGAP] Decode IE RRCEstablishmentCause        AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:921 free5gc/src/amf/ngap.HandleInitialUEMessage() [NGAP] Decode IE UEContextRequest             AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:4142 free5gc/src/amf/ngap.printRanInfo() IP[10.0.50.2:9487] GNbId[00000000]            AMF=NGAP
DEBU[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:951 free5gc/src/amf/ngap.HandleInitialUEMessage() New RanUe [RanUeNgapID: 0]                    AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:996 free5gc/src/amf/ngap.HandleInitialUEMessage() [Initial UE Message] RRC Establishment Cause[3]  AMF=NGAP
DEBU[2020-08-05T16:08:50+01:00]/src/amf/ngap/handler.go:1001 free5gc/src/amf/ngap.HandleInitialUEMessage() Trigger initial Context Setup procedure       AMF=NGAP
TRAC[2020-08-05T16:08:50+01:00]/src/amf/nas/nas_security/security.go:90 free5gc/src/amf/nas/nas_security.Decode() securityHeaderType is  0                      AMF=NAS
INFO[2020-08-05T16:08:50+01:00]/src/amf/gmm/handler.go:528 free5gc/src/amf/gmm.HandleRegistrationRequest() [AMF] Handle Registration Request             AMF=Gmm
DEBU[2020-08-05T16:08:50+01:00]/src/amf/gmm/handler.go:549 free5gc/src/amf/gmm.HandleRegistrationRequest() RegistrationType: Initial Registration        AMF=Gmm
DEBU[2020-08-05T16:08:50+01:00]/src/amf/gmm/handler.go:573 free5gc/src/amf/gmm.HandleRegistrationRequest() SUCI: suci-0-208-930-0-0-0-000000003          AMF=Gmm
INFO[2020-08-05T16:08:50+01:00]/src/amf/gmm/handler.go:630 free5gc/src/amf/gmm.HandleRegistrationRequest() ue.Capability5GMM is nil in InitialUEMEssage  AMF=Gmm
TRAC[2020-08-05T16:08:50+01:00]/src/amf/gmm/sm.go:72 free5gc/src/amf/gmm.register_event_3gpp() amfUe.RegistrationType5GS
1                   AMF=Gmm
INFO[2020-08-05T16:08:50+01:00]/src/amf/gmm/handler.go:1644 free5gc/src/amf/gmm.startAuthenticationProcedure() Start authentication procedure                AMF=Gmm
2020/08/05 16:08:50 map[$and:[map[nfType:AUSF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:50 | 200 |   23.603818ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=AUSF
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:64 free5gc/src/ausf/producer.HandleUeAuthPostRequest() HandleUeAuthPostRequest                       AUSF=UeAuthPost
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:96 free5gc/src/ausf/producer.UeAuthPostRequestProcedure() Serving network authorized                    AUSF=UeAuthPost
2020/08/05 16:08:51 map[$and:[map[nfType:UDM] map[$or:[map[allowedNfTypes:AUSF] map[allowedNfTypes:map[$exists:false]]]] map[nfServices:map[$elemMatch:map[nfServiceStatus:REGISTERED serviceName:map[$in:[nudm-ueau]]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   77.173515ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AUSF&service-names=nudm-ueau&target-nf-type=UDM
INFO[2020-08-05T16:08:51+01:00]/lib/util_3gpp/suci/toSupi.go:260 free5gc/lib/util_3gpp/suci.ToSupi() suciPart [suci 0 208 930 0 0 0 000000003]     UDM=UEAU
INFO[2020-08-05T16:08:51+01:00]/lib/util_3gpp/suci/toSupi.go:278 free5gc/lib/util_3gpp/suci.ToSupi() scheme 0                                      UDM=UEAU
INFO[2020-08-05T16:08:51+01:00]/lib/util_3gpp/suci/toSupi.go:285 free5gc/lib/util_3gpp/suci.ToSupi() SUPI type is IMSI                             UDM=UEAU
INFO[2020-08-05T16:08:51+01:00]/src/udm/producer/generate_auth_data.go:35 free5gc/src/udm/producer.HandleGenerateAuthData() supi conversion => imsi-208930000000003       UDM=UEAU
http://10.5.23.30:29510
2020/08/05 16:08:51 map[$and:[map[nfType:UDR] map[$or:[map[allowedNfTypes:UDM] map[allowedNfTypes:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   25.014597ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=UDM&target-nf-type=UDR
[GIN] 2020/08/05 - 16:08:51 | 200 |    4.740141ms |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/authentication-data/authentication-subscription
INFO[2020-08-05T16:08:51+01:00]/src/udm/producer/generate_auth_data.go:103 free5gc/src/udm/producer.HandleGenerateAuthData() Nil Opc                                       UDM=UEAU
[GIN] 2020/08/05 - 16:08:51 | 200 |   40.031359ms |       127.0.0.1 | POST     /nudm-ueau/v1/suci-0-208-930-0-0-0-000000003/security-information/generate-auth-data
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:124 free5gc/src/ausf/producer.UeAuthPostRequestProcedure() Add SuciSupiPair (suci-0-208-930-0-0-0-000000003, imsi-208930000000003) to map.  AUSF=UeAuthPost
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:130 free5gc/src/ausf/producer.UeAuthPostRequestProcedure() Use 5G AKA auth method                        AUSF=UeAuthPost
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:138 free5gc/src/ausf/producer.UeAuthPostRequestProcedure() XresStar = 3261623433366536636438373962346132623032343231646333613033333935  AUSF=5gAkaComfirm
[GIN] 2020/08/05 - 16:08:51 | 201 |  123.748145ms |       127.0.0.1 | POST     /nausf-auth/v1/ue-authentications
INFO[2020-08-05T16:08:51+01:00]/src/amf/gmm/message/send.go:65 free5gc/src/amf/gmm/message.SendAuthenticationRequest() [NAS] Send Authentication Request[Retry: 0]   AMF=Gmm
INFO[2020-08-05T16:08:51+01:00]/src/amf/ngap/message/send.go:138 free5gc/src/amf/ngap/message.SendDownlinkNasTransport() [AMF] Send Downlink Nas Transport             AMF=NGAP
DEBU[2020-08-05T16:08:51+01:00]/src/amf/ngap/message/send.go:32 free5gc/src/amf/ngap/message.SendToRan() [NGAP] Send To Ran [IP: 10.0.50.2:9487]       AMF=NGAP
DEBU[2020-08-05T16:08:51+01:00]/src/amf/ngap/sctp/sctp.go:100 free5gc/src/amf/ngap/sctp.(*SCTPListener).forwardData() Packet get: 0x002e403c000004000a0002000100550002000000260016157e00572d102ab436e6cd879b4a2b02421dc3a033950079400f4002f839000000001002f839000001  AMF=NGAP
INFO[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:180 free5gc/src/amf/ngap.HandleUplinkNasTransport() [AMF] Uplink Nas Transport                    AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:187 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE AmfUeNgapID                  AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:194 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE RanUeNgapID                  AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:201 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE NasPdu                       AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:208 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE UserLocationInformation      AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:4142 free5gc/src/amf/ngap.printRanInfo() IP[10.0.50.2:9487] GNbId[00000000]            AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:233 free5gc/src/amf/ngap.HandleUplinkNasTransport() RANUENGAPID[0] AMFUENGAPID[1]                 AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:90 free5gc/src/amf/nas/nas_security.Decode() securityHeaderType is  0                      AMF=NAS
INFO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:1957 free5gc/src/amf/gmm.HandleAuthenticationResponse() [AMF] Handle Authentication Response          AMF=Gmm
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:46 free5gc/src/ausf/producer.HandleAuth5gAkaComfirmRequest() Auth5gAkaComfirmRequest                       AUSF=5gAkaComfirm
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:241 free5gc/src/ausf/producer.Auth5gAkaComfirmRequestProcedure() res*: 3261623433366536636438373962346132623032343231646333613033333935
Xres*: 3261623433366536636438373962346132623032343231646333613033333935  AUSF=5gAkaComfirm
INFO[2020-08-05T16:08:51+01:00]/src/ausf/producer/ue_authentication.go:246 free5gc/src/ausf/producer.Auth5gAkaComfirmRequestProcedure() 5G AKA confirmation succeeded                 AUSF=5gAkaComfirm
[GIN] 2020/08/05 - 16:08:51 | 204 |      1.4977ms |       127.0.0.1 | PUT      /nudr-dr/v1/subscription-data/imsi-208930000000003/authentication-data/authentication-status
[GIN] 2020/08/05 - 16:08:51 | 201 |    2.338889ms |       127.0.0.1 | POST     /nudm-ueau/v1/imsi-208930000000003/auth-events
[GIN] 2020/08/05 - 16:08:51 | 200 |    4.072732ms |       127.0.0.1 | PUT      /nausf-auth/v1/ue-authentications/suci-0-208-930-0-0-0-000000003/5g-aka-confirmation
DEBU[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:2006 free5gc/src/amf/gmm.HandleAuthenticationResponse() ue.DerivateKamf() 85aecdc9090fe87886017c7c58b6cda1cfe7699355c8938989ab6eab53dca6c8  AMF=Gmm
INFO[2020-08-05T16:08:51+01:00]/src/amf/gmm/message/send.go:165 free5gc/src/amf/gmm/message.SendSecurityModeCommand() [NAS] Send Security Mode Command              AMF=Gmm
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:40 free5gc/src/amf/nas/nas_security.Encode() ue.CipheringAlg 0                             AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:41 free5gc/src/amf/nas/nas_security.Encode() ue.DLCount() 0                                AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:42 free5gc/src/amf/nas/nas_security.Encode() payload [126 0 93 2 0 2 240 240 225 54 1 0]   AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:60 free5gc/src/amf/nas/nas_security.Encode() mac32 [96 60 29 94]                           AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:66 free5gc/src/amf/nas/nas_security.Encode() Encode payload [126 3 96 60 29 94 0 126 0 93 2 0 2 240 240 225 54 1 0]  AMF=NAS
INFO[2020-08-05T16:08:51+01:00]/src/amf/ngap/message/send.go:138 free5gc/src/amf/ngap/message.SendDownlinkNasTransport() [AMF] Send Downlink Nas Transport             AMF=NGAP
DEBU[2020-08-05T16:08:51+01:00]/src/amf/ngap/message/send.go:32 free5gc/src/amf/ngap/message.SendToRan() [NGAP] Send To Ran [IP: 10.0.50.2:9487]       AMF=NGAP
DEBU[2020-08-05T16:08:51+01:00]/src/amf/ngap/sctp/sctp.go:100 free5gc/src/amf/ngap/sctp.(*SCTPListener).forwardData() Packet get: 0x002e4061000004000a000200010055000200000026003b3a7e0402cd7727007e005e7700091530014100002100f07100217e004109000d01020839f0ff000000000000f31001012e02f0f02f0504010102030079400f4002f839000000001002f839000001  AMF=NGAP
INFO[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:180 free5gc/src/amf/ngap.HandleUplinkNasTransport() [AMF] Uplink Nas Transport                    AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:187 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE AmfUeNgapID                  AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:194 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE RanUeNgapID                  AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:201 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE NasPdu                       AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:208 free5gc/src/amf/ngap.HandleUplinkNasTransport() [NGAP] Decode IE UserLocationInformation      AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:4142 free5gc/src/amf/ngap.printRanInfo() IP[10.0.50.2:9487] GNbId[00000000]            AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/ngap/handler.go:233 free5gc/src/amf/ngap.HandleUplinkNasTransport() RANUENGAPID[0] AMFUENGAPID[1]                 AMF=NGAP
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:90 free5gc/src/amf/nas/nas_security.Decode() securityHeaderType is  4                      AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:103 free5gc/src/amf/nas/nas_security.Decode() securityHeaderType is  4                      AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:105 free5gc/src/amf/nas/nas_security.Decode() securityHeader is  [126 4 2 205 119 39]       AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:107 free5gc/src/amf/nas/nas_security.Decode() sequenceNumber 0                              AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:133 free5gc/src/amf/nas/nas_security.Decode() cmac value: 0x
 [2 205 119 39]                AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:138 free5gc/src/amf/nas/nas_security.Decode() ue.CipheringAlg 0                             AMF=NAS
INFO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:2162 free5gc/src/amf/gmm.HandleSecurityModeComplete() [AMF] Handle Security Mode Complete           AMF=Gmm
TRAC[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:2187 free5gc/src/amf/gmm.HandleSecurityModeComplete() [AMF] Handle MsgTypeRegistrationRequest       AMF=Gmm
INFO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:528 free5gc/src/amf/gmm.HandleRegistrationRequest() [AMF] Handle Registration Request             AMF=Gmm
DEBU[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:549 free5gc/src/amf/gmm.HandleRegistrationRequest() RegistrationType: Initial Registration        AMF=Gmm
DEBU[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:573 free5gc/src/amf/gmm.HandleRegistrationRequest() SUCI: suci-0-208-930-0-0-0-000000003          AMF=Gmm
TRAC[2020-08-05T16:08:51+01:00]/src/amf/gmm/sm.go:72 free5gc/src/amf/gmm.register_event_3gpp() amfUe.RegistrationType5GS
1                   AMF=Gmm
2020/08/05 16:08:51 map[$and:[map[nfType:UDM] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]] map[$or:[map[udmInfo.supiRanges:map[$elemMatch:map[end:map[$gte:208930000000003] start:map[$lte:208930000000003]]]] map[udmInfo.externalGroupIdentifiersRanges:map[$exists:false] udmInfo.gpsiRanges:map[$exists:false] udmInfo.supiRanges:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   70.786641ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-208930000000003&target-nf-type=UDM
INFO[2020-08-05T16:08:51+01:00]/src/udr/producer/data_repository.go:40 free5gc/src/udr/producer.HandleQueryAmData() HandleQueryAmData                             UDR=DataRepo
[GIN] 2020/08/05 - 16:08:51 | 404 |     919.761µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=
[GIN] 2020/08/05 - 16:08:51 | 404 |    1.757469ms |       127.0.0.1 | GET      /nudm-sdm/v1/imsi-208930000000003/nssai?plmn-id=208930
ERRO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:1343 free5gc/src/amf/gmm.getSubscribedNssai() SDM_Get Slice Selection Subscription Data Failed Problem[&{Type: Title: Status:0 Detail: Instance: Cause:USER_NOT_FOUND InvalidParams:[]}]  AMF=Gmm
DEBU[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:1357 free5gc/src/amf/gmm.handleRequestedNssai() RequestedNssai: [{Sst:1 Sd:010203}]           AMF=Gmm
2020/08/05 16:08:51 map[$and:[map[nfType:NSSF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   38.500323ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=NSSF
INFO[2020-08-05T16:08:51+01:00] Request received - NSSelectionGet             NSSF=nsselection
[GIN] 2020/08/05 - 16:08:51 | 200 |     953.946µs |       127.0.0.1 | GET      /nnssf-nsselection/v1/network-slice-information?nf-id=f84bc0c0-ff0e-4142-a08d-6a8957989cbc&nf-type=AMF&slice-info-request-for-registration=%7B%22requestedNssai%22%3A%5B%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D%5D%7D
ERRO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:1408 free5gc/src/amf/gmm.handleRequestedNssai() Registration Status Update Error[: server no response]  AMF=Gmm
2020/08/05 16:08:51 map[$and:[map[nfType:AMF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   43.457986ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=AMF
ERRO[2020-08-05T16:08:51+01:00]/src/amf/producer/callback/n1n2message.go:115 free5gc/src/amf/producer/callback.SendN1MessageNotifyAtAMFReAllocation() unsupported scheme[]                          AMF=HTTP
2020/08/05 16:08:51 map[$and:[map[nfType:UDM] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]] map[$or:[map[udmInfo.supiRanges:map[$elemMatch:map[end:map[$gte:208930000000003] start:map[$lte:208930000000003]]]] map[udmInfo.externalGroupIdentifiersRanges:map[$exists:false] udmInfo.gpsiRanges:map[$exists:false] udmInfo.supiRanges:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   72.779413ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-208930000000003&target-nf-type=UDM
[GIN] 2020/08/05 - 16:08:51 | 204 |    4.460741ms |       127.0.0.1 | PUT      /nudr-dr/v1/subscription-data/imsi-208930000000003/context-data/amf-3gpp-access
[GIN] 2020/08/05 - 16:08:51 | 201 |    5.514468ms |       127.0.0.1 | PUT      /nudm-uecm/v1/imsi-208930000000003/registrations/amf-3gpp-access
INFO[2020-08-05T16:08:51+01:00]/src/udr/producer/data_repository.go:40 free5gc/src/udr/producer.HandleQueryAmData() HandleQueryAmData                             UDR=DataRepo
[GIN] 2020/08/05 - 16:08:51 | 404 |      766.04µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=
[GIN] 2020/08/05 - 16:08:51 | 404 |    1.218153ms |       127.0.0.1 | GET      /nudm-sdm/v1/imsi-208930000000003/am-data?plmn-id=208930
ERRO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:852 free5gc/src/amf/gmm.HandleInitialRegistration() SDM_Get AmData Failed Problem[&{Type: Title: Status:0 Detail: Instance: Cause:USER_NOT_FOUND InvalidParams:[]}]  AMF=Gmm
[GIN] 2020/08/05 - 16:08:51 | 404 |     429.593µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/smf-selection-subscription-data?supported-features=
[GIN] 2020/08/05 - 16:08:51 | 404 |    1.681369ms |       127.0.0.1 | GET      /nudm-sdm/v1/imsi-208930000000003/smf-select-data?plmn-id=208930
ERRO[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:859 free5gc/src/amf/gmm.HandleInitialRegistration() SDM_Get SmfSelectData Failed Problem[&{Type: Title: Status:0 Detail: Instance: Cause:USER_NOT_FOUND InvalidParams:[]}]  AMF=Gmm
[GIN] 2020/08/05 - 16:08:51 | 200 |     483.885µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/context-data/smf-registrations?supported-features=
[GIN] 2020/08/05 - 16:08:51 | 200 |    1.137895ms |       127.0.0.1 | GET      /nudm-sdm/v1/imsi-208930000000003/ue-context-in-smf-data
http://10.5.23.30:29510
2020/08/05 16:08:51 map[$and:[map[nfType:UDR] map[$or:[map[allowedNfTypes:UDM] map[allowedNfTypes:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   29.007289ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=UDM&target-nf-type=UDR
[GIN] 2020/08/05 - 16:08:51 | 201 |       99.14µs |       127.0.0.1 | POST     /nudr-dr/v1/subscription-data/imsi-208930000000003/context-data/sdm-subscriptions
[GIN] 2020/08/05 - 16:08:51 | 201 |   36.749116ms |       127.0.0.1 | POST     /nudm-sdm/v1/imsi-208930000000003/sdm-subscriptions
2020/08/05 16:08:51 map[$and:[map[nfType:PCF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]] map[$or:[map[pcfInfo.supiRanges:map[$elemMatch:map[end:map[$gte:208930000000003] start:map[$lte:208930000000003]]]] map[pcfInfo.supiRanges:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   97.892261ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-208930000000003&target-nf-type=PCF
TRAC[2020-08-05T16:08:51+01:00]/src/pcf/producer/ampolicy.go:148 free5gc/src/pcf/producer.PostPolicies() Handle Policy Association Request             PCF=ampolicy
2020/08/05 16:08:51 map[$and:[map[nfType:UDR] map[$or:[map[allowedNfTypes:PCF] map[allowedNfTypes:map[$exists:false]]]]]]
[GIN] 2020/08/05 - 16:08:51 | 200 |   28.823113ms |      10.5.23.30 | GET      /nnrf-disc/v1/nf-instances?requester-nf-type=PCF&target-nf-type=UDR
[GIN] 2020/08/05 - 16:08:51 | 200 |     509.854µs |       127.0.0.1 | GET      /nudr-dr/v1/policy-data/ues/imsi-208930000000003/am-data
TRAC[2020-08-05T16:08:51+01:00]/src/pcf/producer/ampolicy.go:211 free5gc/src/pcf/producer.PostPolicies() AMPolicy association Id[imsi-208930000000003-1] Create  PCF=ampolicy
[GIN] 2020/08/05 - 16:08:51 | 201 |   34.657303ms |       127.0.0.1 | POST     /npcf-am-policy-control/v1/policies
DEBU[2020-08-05T16:08:51+01:00]/src/amf/consumer/am_policy.go:41 free5gc/src/amf/consumer.AMPolicyControlCreate() location header: http://0.0.0.0:29507/npcf-am-policy-control/v1/policies/imsi-208930000000003-1  AMF=Consumer
DEBU[2020-08-05T16:08:51+01:00]/src/amf/consumer/am_policy.go:61 free5gc/src/amf/consumer.AMPolicyControlCreate() UE AM Policy Association ID: imsi-208930000000003-1  AMF=Consumer
DEBU[2020-08-05T16:08:51+01:00]/src/amf/consumer/am_policy.go:62 free5gc/src/amf/consumer.AMPolicyControlCreate() AmPolicyAssociation: &{Request:0xc0006e4480 Triggers:[] ServAreaRes:<nil> Rfsp:0 Pras:map[] SuppFeat:}  AMF=Consumer
DEBU[2020-08-05T16:08:51+01:00]/src/amf/gmm/handler.go:938 free5gc/src/amf/gmm.HandleInitialRegistration() Allocate GUTI[20893cafe0000000001]            AMF=Gmm
INFO[2020-08-05T16:08:51+01:00]/src/amf/gmm/message/send.go:211 free5gc/src/amf/gmm/message.SendRegistrationAccept() [NAS] Send Registration Accept                AMF=Gmm
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:40 free5gc/src/amf/nas/nas_security.Encode() ue.CipheringAlg 0                             AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:41 free5gc/src/amf/nas/nas_security.Encode() ue.DLCount() 1                                AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:42 free5gc/src/amf/nas/nas_security.Encode() payload [126 0 66 1 1 119 0 11 2 2 248 57 202 254 0 0 0 0 1 84 7 0 2 248 57 0 0 1 17 5 64 1 1 2 3 94 1 6 22 1 44]  AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:60 free5gc/src/amf/nas/nas_security.Encode() mac32 [24 46 121 131]                         AMF=NAS
TRAC[2020-08-05T16:08:51+01:00]/src/amf/nas/nas_security/security.go:66 free5gc/src/amf/nas/nas_security.Encode() Encode payload [126 2 24 46 121 131 1 126 0 66 1 1 119 0 11 2 2 248 57 202 254 0 0 0 0 1 84 7 0 2 248 57 0 0 1 17 5 64 1 1 2 3 94 1 6 22 1 44]  AMF=NAS
INFO[2020-08-05T16:08:51+01:00]/src/amf/ngap/message/send.go:340 free5gc/src/amf/ngap/message.SendInitialContextSetupRequest() [AMF] Send Initial Context Setup Request      AMF=NGAP
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x58 pc=0x969b5b]

goroutine 10 [running]:
free5gc/src/amf/ngap/message.BuildIEMobilityRestrictionList(0xc0000c3080, 0xc00078ba68, 0x3, 0x8, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/admin5g/free5gc/src/amf/ngap/message/forward_ie.go:77 +0xbb
free5gc/src/amf/ngap/message.BuildInitialContextSetupRequest(0xc0000c3080, 0xdaa054, 0xb, 0xc000029a10, 0x30, 0x30, 0x0, 0x0, 0x0, 0x0, ...)
        /home/admin5g/free5gc/src/amf/ngap/message/build.go:1066 +0x1be3
free5gc/src/amf/ngap/message.SendInitialContextSetupRequest(0xc0000c3080, 0xdaa054, 0xb, 0xc000029a10, 0x30, 0x30, 0x0, 0x0, 0x0, 0x0)
        /home/admin5g/free5gc/src/amf/ngap/message/send.go:354 +0x131
free5gc/src/amf/gmm/message.SendRegistrationAccept(0xc0000c3080, 0xdaa054, 0xb, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/admin5g/free5gc/src/amf/gmm/message/send.go:218 +0x23c
free5gc/src/amf/gmm.HandleInitialRegistration(0xc0000c3080, 0xdaa054, 0xb, 0x2, 0x2)
        /home/admin5g/free5gc/src/amf/gmm/handler.go:951 +0x93c
free5gc/src/amf/gmm.register_event_3gpp(0xc00080d280, 0xdaa11a, 0xb, 0xc0009267b0, 0xd53500, 0xc000787b00)
        /home/admin5g/free5gc/src/amf/gmm/sm.go:75 +0x432
free5gc/src/amf/gmm.Registered_3gpp(0xc00080d280, 0xdaa11a, 0xb, 0xc0009267b0, 0xc00088ce60, 0x0)
        /home/admin5g/free5gc/src/amf/gmm/sm.go:24 +0x49
free5gc/lib/fsm.(*FSM).SendEvent(...)
        /home/admin5g/free5gc/lib/fsm/fsm.go:57
free5gc/src/amf/gmm.HandleSecurityModeComplete(0xc0000c3080, 0xdaa054, 0xb, 0x2e, 0xc000952c40, 0xc000787904, 0x1400000000d535c0, 0xc00082d738)
        /home/admin5g/free5gc/src/amf/gmm/handler.go:2193 +0x751
free5gc/src/amf/gmm.SecurityMode_3gpp(0xc00080d280, 0xdaa11a, 0xb, 0xc0009266c0, 0xc00088ce70, 0xeeaa80)
        /home/admin5g/free5gc/src/amf/gmm/sm.go:116 +0x31f
free5gc/lib/fsm.(*FSM).SendEvent(...)
        /home/admin5g/free5gc/lib/fsm/fsm.go:57
free5gc/src/amf/nas.Dispatch(0xc0000c3080, 0xdaa054, 0xb, 0x2e, 0xc000952ae0, 0x33, 0x39)
        /home/admin5g/free5gc/src/amf/nas/dispatch.go:19 +0x2b5
free5gc/src/amf/nas.HandleNAS(0xc000786d80, 0x2e, 0xc000946680, 0x3a, 0x40)
        /home/admin5g/free5gc/src/amf/nas/handler.go:41 +0x11a
free5gc/src/amf/ngap.HandleUplinkNasTransport(0xc00079c310, 0xc000921900)
        /home/admin5g/free5gc/src/amf/ngap/handler.go:239 +0x731
free5gc/src/amf/ngap.Dispatch(0xc00078abd0, 0xe, 0xc000900000, 0x65, 0x2000)
        /home/admin5g/free5gc/src/amf/ngap/dispatcher.go:45 +0x51a
free5gc/src/amf/handler.Handle()
        /home/admin5g/free5gc/src/amf/handler/handler.go:35 +0x1db
created by free5gc/src/amf/service.(*AMF).Start
        /home/admin5g/free5gc/src/amf/service/amf_init.go:150 +0x518

jay16213 · December 30, 2020, 3:40am

This error is caused because AMF cannot get subscribe data of UE from UDM, you need to insert a subscriber (UE data) before running the test. You can do it via free5gc web UI or mongodb cli tools

dlake02 · December 30, 2020, 3:40am

I have a user. This is my MongoDB:

> use free5gc

switched to db free5gc

> ls

[native code]

> show collections

NfProfile

policyData.ues.amData

policyData.ues.smData

subscriptionData.authenticationData.authenticationStatus

subscriptionData.authenticationData.authenticationSubscription

subscriptionData.contextData.amf3gppAccess

subscriptionData.provisionedData.amData

subscriptionData.provisionedData.smData

subscriptionData.provisionedData.smfSelectionSubscriptionData

urilist

> db.subscriptionData.provisionedData.smfSelectionSubscriptionData.find()

{ "_id" : ObjectId("5f2b3da520781a45a76133d6"), "subscribedSnssaiInfos" : { "01010203" : { "dnnInfos" : [ { "dnn" : "internet" } ] }, "01112233" : { "dnnInfos" : [ { "dnn" : "internet" } ] } }, "ueId" : "imsi-208930000000003", "servingPlmnId" : "20893" }

> db.subscriptionData.subscriptionData.authenticationData.authenticationStatus.find()

> db.subscriptionData.authenticationData.authenticationSubscription.find()

{ "_id" : ObjectId("5f2b3da520781a45a76133d3"), "permanentKey" : { "encryptionKey" : 0, "encryptionAlgorithm" : 0, "permanentKeyValue" : "8baf473f2f8fd09487cccbd7097c6862" }, "sequenceNumber" : "16f3b3f70fc2", "authenticationManagementField" : "8000", "milenage" : { "op" : { "encryptionAlgorithm" : 0, "opValue" : "8e27b6af0e692e750f32667a3b14605d", "encryptionKey" : 0 } }, "opc" : { "opcValue" : "", "encryptionKey" : 0, "encryptionAlgorithm" : 0 }, "ueId" : "imsi-208930000000003", "authenticationMethod" : "5G_AKA" }

>

This is the error I’m seeing in the log:

free5gc/src/udr/producer.HandleQueryAmData() HandleQueryAmData                             UDR=DataRepo
[GIN] 2020/08/06 - 00:16:14 | 404 |     722.181µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=
[GIN] 2020/08/06 - 00:16:14 | 404 |    1.545645ms |       127.0.0.1 | GET      /nudm-sdm/v1/imsi-208930000000003/am-data?plmn-id=208930
ERRO[2020-08-06T00:16:14+01:00]/src/amf/gmm/handler.go:852 free5gc/src/amf/gmm.HandleInitialRegistration() SDM_Get AmData Failed Problem[&{Type: Title: Status:0 Detail: Instance: Cause:USER_NOT_FOUND InvalidParams:[]}]  AMF=Gmm
[GIN] 2020/08/06 - 00:16:14 | 404 |         412µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/smf-selection-subscription-data?supported-features=
[GIN] 2020/08/06 - 00:16:14 | 404 |    1.001401ms |       127.0.0.1 | GET      /nudm-sdm/v1/imsi-208930000000003/smf-select-data?plmn-id=208930
ERRO[2020-08-06T00:16:14+01:00]/src/amf/gmm/handler.go:859 free5gc/src/amf/gmm.HandleInitialRegistration() SDM_Get SmfSelectData Failed Problem[&{Type: Title: Status:0 Detail: Instance: Cause:USER_NOT_FOUND InvalidParams:[]}]  AMF=Gmm

dlake02 · December 30, 2020, 3:40am

This is an incoming session with strace running against the udm NF. I’m seeing “resource unavailable” in the trace and then USER_NOT_FOUND.
new 46.txt (39.1 KB)

dlake02 · December 30, 2020, 3:40am

Update but still no solution.

I’ve noticed that in my trace, the Upling NASTransport Security Header is set to 0100:

In working traces that I’ve seen, it is set to 0010:

I’m using a Spirent Landslide generator. I have the following set:

NAS-5G Version (24.501) 15.4.0 (Jun 2019)
NGAP Version (38.413) 15.4.0 (Jul 2019)

Security Version (33.501) 15.5.0 (Jun 2019)

Are these the correct supported versions?

Thanks

David

One other thing.

The URI to the UDR is /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=

If I try this from the CLI I get “404 Not Found”.

CLI below:

root@Free5GC-CP:~/free5gc/log# wget 127.0.0.1:29504/nudr-dr/v1/subscription-data/imsi-208930000000003/authentication-data/authentication-subscription
--2020-08-07 22:11:24--  http://127.0.0.1:29504/nudr-dr/v1/subscription-data/imsi-208930000000003/authentication-data/authentication-subscription
Connecting to 127.0.0.1:29504... connected.
[GIN] 2020/08/07 - 22:11:24 | 200 |     605.874µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/authentication-data/authentication-subscription
HTTP request sent, awaiting response... 200 OK
Length: 452 [application/json]
Saving to: ‘authentication-subscription.1’

authentication-subscription.1                               100%[========================================================================================================================================>]     452  --.-KB/s    in 0s

2020-08-07 22:11:24 (73.6 MB/s) - ‘authentication-subscription.1’ saved [452/452]

root@Free5GC-CP:~/free5gc/log# wget http://127.0.0.1:29504/nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=
--2020-08-07 22:11:29--  http://127.0.0.1:29504/nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=
Connecting to 127.0.0.1:29504... connected.
INFO[2020-08-07T22:11:29+01:00]/src/udr/producer/data_repository.go:40 free5gc/src/udr/producer.HandleQueryAmData() HandleQueryAmData                             UDR=DataRepo
HTTP request sent, awaiting response... [GIN] 2020/08/07 - 22:11:29 | 404 |     748.679µs |       127.0.0.1 | GET      /nudr-dr/v1/subscription-data/imsi-208930000000003/208930/provisioned-data/am-data?supported-features=
404 Not Found
2020-08-07 22:11:29 ERROR 404: Not Found.

root@Free5GC-CP:~/free5gc/log#

dlake02 · December 30, 2020, 3:40am

Update. I have found the issue. My SUPI was set with MNC=3 digits but I was using 208 and 93.

This is causing the “USER_NOT_FOUND” but instead of rejecting the setup, the AMF is continuing and then crashing.

One other issue on UP addresses but I will raise another email for that.