search

fasferraz / NWu-Non3GPP-5GC

NWu IKEv2/IPSec Dialer for 5GC / N3IWF
GNU General Public License v3.0
29 stars 16 forks source link

PDUSessionResourceSetupResponseTransfer failed: sequence truncated #3

Closed Aravindchockaiaahkannan closed 2 years ago

Aravindchockaiaahkannan commented 2 years ago

In the stage 7,

Preparing REGISTRATION COMPLETE to send... Preparing UL NAS TRANSPORT message with container PDU SESSION ESTABLISHMENT REQUEST to send...

there was no tun3 created. tun2 was created. but i can see the UE in the dashboard of the webconsole of free5gc.

the free5gc logs:

2022-02-15T12:57:10Z [INFO][N3IWF][NGAP] [N3IWF] Handle PDU Session Resource Setup Request 2022-02-15T12:57:15Z [ERRO][N3IWF][GTP] Dial to UPF failed: read udp 192.168.57.103:2152: i/o timeout 2022-02-15T12:57:15Z [ERRO][N3IWF][NGAP] Setup GTP connection with UPF failed: Dial failed 2022-02-15T12:57:15Z [INFO][N3IWF][NGAP] [N3IWF] Send PDU Session Resource Setup Response 2022-02-15T12:57:15Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:58100] Handle PDU Session Resource Setup Response 2022-02-15T12:57:15Z [INFO][SMF][PduSess] Receive Update SM Context Request 2022-02-15T12:57:15Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-02-15T12:57:15Z [ERRO][SMF][PduSess] Handle PDUSessionResourceSetupResponseTransfer failed: sequence truncated 2022-02-15T12:57:15Z [WARN][SMF][PduSess] SM Context State [Active] shouldn't be here 2022-02-15T12:57:15Z [INFO][SMF][GIN] | 200 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:ba409af8-11e8-4eaa-b406-5c42034415cb/modify |

I am using two VM in the same host machine.

fasferraz commented 2 years ago

Hi, Those messages in the free5gc log are after the N3IWF received the PDU Session Establishment Request from the UE. It looks something is failing in the free5gc with the UPF. The userplane SA child is not being created...

Can you increase the log level do debug?

In version 3.0.6 the free5GC does not send yet the PDU Session Establishment Accepted to the UE. If you want to add this you need to modify NFs/n3iwf/ngap/handler/handler.go file and add some code: https://github.com/fasferraz/n3iwf/commit/7226b0e1dc43fdd617a7f5f334443268ae9dbc88, and rebuild the N3IWF again (make n3iwf) Nevertheless, this will only happen if everything is ok with session creation, which is not the case with your logs, since you have some internal errors...

This is my log:

2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810] Handle Uplink Nas Transport 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle Registration Complete 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810] Handle Uplink Nas Transport 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle UL NAS Transport 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Transport 5GSM Message to SMF 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Select SMF [snssai: {Sst:1 Sd:010203}, dnn: internet] 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=NSSF | 2022-02-15T14:03:54Z [INFO][NSSF][NsSelect] Handle NSSelectionGet 2022-02-15T14:03:54Z [INFO][NSSF][GIN] | 200 | 127.0.0.1 | GET | /nnssf-nsselection/v1/network-slice-information?nf-id=f78285c9-0672-4a0d-b784-a5a2f0e3daae&nf-type=AMF&slice-info-request-for-pdu-session=%7B%22sNssai%22%3A%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D%2C%22roamingIndication%22%3A%22NON_ROAMING%22%7D | 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?dnn=internet&preferred-locality=area1&requester-nf-type=AMF&service-names=nsmf-pdusession&snssais=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D&target-nf-type=SMF&target-plmn-list=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:03:54Z [INFO][SMF][PduSess] Recieve Create SM Context Request 2022-02-15T14:03:54Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-type=UDM | 2022-02-15T14:03:54Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2022-02-15T14:03:54Z [INFO][SMF][CTX] Allocated UE IP address: 60.60.0.1 2022-02-15T14:03:54Z [INFO][SMF][CTX] Selected UPF: UPF 2022-02-15T14:03:54Z [INFO][SMF][PduSess] UE[imsi-2089300007487] PDUSessionID[5] IP[60.60.0.1] 2022-02-15T14:03:54Z [INFO][UDM][SDM] Handle GetSmData 2022-02-15T14:03:54Z [INFO][UDM][SDM] getSmDataProcedure: SUPI[imsi-2089300007487] PLMNID[20893] DNN[internet] SNssai[{"sst":1,"sd":"010203"}] 2022-02-15T14:03:54Z [INFO][UDR][DRepo] Handle QuerySmData 2022-02-15T14:03:54Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/sm-data?single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:03:54Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/sm-data?dnn=internet&plmn-id=20893&single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:03:54Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2022-02-15T14:03:54Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc00000cae0] 2022-02-15T14:03:54Z [INFO][SMF][GSM] Protocol Configuration Options 2022-02-15T14:03:54Z [INFO][SMF][GSM] &{[0xc00000cae0]} 2022-02-15T14:03:54Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-2089300007487] PDUSessionID[5] 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-type=PCF | 2022-02-15T14:03:54Z [INFO][PCF][SMpolicy] Handle CreateSmPolicy 2022-02-15T14:03:54Z [INFO][UDR][DRepo] Handle PolicyDataUesUeIdSmDataGet 2022-02-15T14:03:54Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/policy-data/ues/imsi-2089300007487/sm-data?dnn=internet&snssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:03:54Z [INFO][PCF][GIN] | 201 | 127.0.0.1 | POST | /npcf-smpolicycontrol/v1/sm-policies | 2022-02-15T14:03:54Z [INFO][SMF][PduSess] SUPI[imsi-2089300007487] has no pre-config route 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-instance-id=f78285c9-0672-4a0d-b784-a5a2f0e3daae&target-nf-type=AMF | 2022-02-15T14:03:54Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2022-02-15T14:03:54Z [INFO][SMF][GIN] | 201 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts | 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] create smContext[pduSessionID: 5] Success 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Session Establishment Response 2022-02-15T14:03:54Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse &{1000 Kbps 1000 Kbps} 2022-02-15T14:03:54Z [INFO][LIB][PFCP] Remove Request Transaction [2] 2022-02-15T14:03:54Z [INFO][AMF][Producer] Handle N1N2 Message Transfer Request 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810][AMF_UE_NGAP_ID:1] Send PDU Session Resource Setup Request 2022-02-15T14:03:54Z [INFO][AMF][GIN] | 200 | 127.0.0.1 | POST | /namf-comm/v1/ue-contexts/imsi-2089300007487/n1-n2-messages | 2022-02-15T14:03:54Z [INFO][N3IWF][NGAP] [N3IWF] Handle PDU Session Resource Setup Request 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Nonce] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Handle CREATE_CHILD_SA 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [SecurityAssociation] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Nonce] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][NGAP] [N3IWF] Send PDU Session Resource Setup Response 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810] Handle PDU Session Resource Setup Response 2022-02-15T14:03:54Z [INFO][SMF][PduSess] Recieve Update SM Context Request 2022-02-15T14:03:54Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Handle PFCP session modification request 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Session Modification Response 2022-02-15T14:03:54Z [INFO][LIB][PFCP] Remove Request Transaction [3] 2022-02-15T14:03:54Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse 2022-02-15T14:03:54Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept 2022-02-15T14:03:54Z [INFO][SMF][PFCP] PFCP Session Modification Success[1] 2022-02-15T14:03:54Z [INFO][SMF][GIN] | 200 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:5d686404-1943-47f8-b83e-d6e66b0cff6a/modify |

Aravindchockaiaahkannan commented 2 years ago

Hello,

I have attached the full free5gc log below. Thanks.

2022-02-15T14:11:44Z [INFO][UPF][Util] Free5GC log: /home/aravind/free5gc/log/free5gc.log 2022-02-15T14:11:44Z [INFO][UPF][Util] UPF log: /home/aravind/free5gc/log/nf/upf.log 2022-02-15T14:11:44Z [INFO][UPF][Util] Config: /home/aravind/free5gc/config/upfcfg.yaml 2022-02-15T14:11:44Z [INFO][UPF][Util] UPF config version [1.0.0] 2022-02-15T14:11:44Z [INFO][UPF][Util] Set log level: info 2022-02-15T14:11:44Z [INFO][UPF][Util] DNN routes added, main routing table: 2022-02-15T14:11:44Z [INFO][UPF][Util] DstIp Gateway Iface Priority RtProto Type 2022-02-15T14:11:44Z [INFO][UPF][Util] 192.168.57.0 /24 0.0.0.0 enp0s9 0 kernel unicast 2022-02-15T14:11:44Z [INFO][UPF][Util] 192.168.56.0 /24 0.0.0.0 enp0s8 0 kernel unicast 2022-02-15T14:11:44Z [INFO][UPF][Util] 60.60.0.0 /24 0.0.0.0 upfgtp 0 static unicast 2022-02-15T14:11:44Z [INFO][UPF][Util] 10.0.2.2 /32 0.0.0.0 enp0s3 100 dhcp unicast 2022-02-15T14:11:44Z [INFO][UPF][Util] 10.0.2.0 /24 0.0.0.0 enp0s3 0 kernel unicast 2022-02-15T14:11:44Z [INFO][UPF][Util] 10.0.0.0 /24 0.0.0.0 ipsec0 0 kernel unicast 2022-02-15T14:11:44Z [INFO][UPF][Util] 0.0.0.0 /0 10.0.2.2 enp0s3 100 dhcp unicast nrf 2022-02-15T14:11:45Z [INFO][NRF][App] NRF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:09:09Z commit hash: e74af1f5 commit time: 2021-08-27T07:54:21Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:45Z [INFO][NRF][Init] NRF Log level is set to [info] level 2022-02-15T14:11:45Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][MonDB] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][MonDB] set report call : false 2022-02-15T14:11:45Z [INFO][NRF][CFG] config version [1.0.0] 2022-02-15T14:11:45Z [INFO][NRF][Init] Server started 2022-02-15T14:11:45Z [INFO][NRF][Init] nrfconfig Info: Version[1.0.0] Description[NRF initial local configuration] 2022-02-15T14:11:45Z [INFO][NRF][Init] Binding addr: [127.0.0.10:8000] 2022-02-15T14:11:45Z [INFO][AMF][App] amf 2022-02-15T14:11:45Z [INFO][AMF][App] AMF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:07:19Z commit hash: 3241cae9 commit time: 2022-01-04T16:20:05Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:45Z [INFO][AMF][Init] AMF Log level is set to [info] level 2022-02-15T14:11:45Z [INFO][LIB][NAS] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][NAS] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][NGAP] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][NGAP] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][FSM] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][FSM] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][Aper] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Aper] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:45Z [INFO][AMF][CFG] config version [1.0.2] 2022-02-15T14:11:45Z [INFO][AMF][Init] Server started 2022-02-15T14:11:45Z [INFO][AMF][Util] amfconfig Info: Version[1.0.2] Description[AMF initial local configuration] 2022-02-15T14:11:45Z [INFO][AMF][NGAP] Listen on 192.168.56.103/127.0.0.1:38412 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:45Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/8e6c1a04-5392-4eb9-bb94-4409289fcd83 2022-02-15T14:11:45Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/8e6c1a04-5392-4eb9-bb94-4409289fcd83 | smf 2022-02-15T14:11:45Z [INFO][SMF][App] SMF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:11:03Z commit hash: 55480238 commit time: 2022-01-04T16:22:46Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:45Z [INFO][SMF][Init] SMF Log level is set to [info] level 2022-02-15T14:11:45Z [INFO][LIB][NAS] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][NAS] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][NGAP] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][NGAP] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][Aper] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Aper] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][PFCP] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][PFCP] set report call : false 2022-02-15T14:11:45Z [INFO][SMF][CFG] SMF config version [1.0.2] 2022-02-15T14:11:45Z [INFO][SMF][CFG] UE-Routing config version [1.0.1] 2022-02-15T14:11:45Z [INFO][SMF][CTX] smfconfig Info: Version[1.0.2] Description[SMF initial local configuration] 2022-02-15T14:11:45Z [INFO][SMF][CTX] Endpoints: [192.168.56.103] 2022-02-15T14:11:45Z [INFO][SMF][Init] Server started 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:45Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/66412a7e-6bbc-4c32-a061-e76d746b802f 2022-02-15T14:11:45Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/66412a7e-6bbc-4c32-a061-e76d746b802f | 2022-02-15T14:11:45Z [INFO][SMF][Init] SMF Registration to NRF {66412a7e-6bbc-4c32-a061-e76d746b802f SMF REGISTERED 0 0xc0002f89a8 0xc0002f89d8 [] [] [127.0.0.2] [] [] [] 0 0 0 area1 0xc0002bedc0 map[] false 0xc0002f88a0 false false []} 2022-02-15T14:11:45Z [INFO][SMF][PFCP] Listen on 127.0.0.1:8805 2022-02-15T14:11:45Z [INFO][SMF][App] Send PFCP Association Request to UPF[127.0.0.8] 2022-02-15T14:11:45Z [INFO][UPF][Util] [PFCP] Handle PFCP association setup request 2022-02-15T14:11:45Z [INFO][UPF][Util] [PFCP] Association Setup Response 2022-02-15T14:11:45Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-02-15T14:11:45Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[127.0.0.8] 2022-02-15T14:11:45Z [INFO][SMF][PFCP] UPF(127.0.0.8)[internet] setup association 2022-02-15T14:11:45Z [INFO][LIB][PFCP] Remove Request Transaction [1] 2022-02-15T14:11:45Z [INFO][UDR][App] udr 2022-02-15T14:11:45Z [INFO][UDR][App] UDR version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:11:16Z commit hash: 66d4d2c1 commit time: 2021-11-06T19:28:20Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:45Z [INFO][UDR][Init] UDR Log level is set to [info] level 2022-02-15T14:11:45Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][MonDB] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][MonDB] set report call : false 2022-02-15T14:11:45Z [INFO][UDR][CFG] config version [1.0.0] 2022-02-15T14:11:45Z [INFO][UDR][Init] UDR Config Info: Version[1.0.0] Description[UDR initial local configuration] 2022-02-15T14:11:45Z [INFO][UDR][Init] Server started 2022-02-15T14:11:45Z [INFO][UDR][Util] udrconfig Info: Version[1.0.0] Description[UDR initial local configuration] 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:45Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/bb457ca9-2bc5-44f3-a1eb-0bb4d0441371 2022-02-15T14:11:45Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/bb457ca9-2bc5-44f3-a1eb-0bb4d0441371 | pcf 2022-02-15T14:11:45Z [INFO][PCF][App] PCF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:10:59Z commit hash: 72c023f8 commit time: 2022-01-04T16:26:32Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:45Z [INFO][PCF][Init] PCF Log level is set to [info] level 2022-02-15T14:11:45Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:45Z [INFO][PCF][CFG] config version [1.0.0] 2022-02-15T14:11:45Z [INFO][PCF][Init] Server started 2022-02-15T14:11:45Z [INFO][PCF][Util] pcfconfig Info: Version[1.0.0] Description[PCF initial local configuration] 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:45Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/5d7ea6ee-529c-49fc-b660-aeafe8326857 2022-02-15T14:11:45Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/5d7ea6ee-529c-49fc-b660-aeafe8326857 | 2022-02-15T14:11:45Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:45Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=PCF&service-names=nudr-dr&target-nf-type=UDR | udm 2022-02-15T14:11:45Z [INFO][UDM][App] UDM version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:11:14Z commit hash: be3e039d commit time: 2021-10-04T10:20:13Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:45Z [INFO][UDM][Init] UDM Log level is set to [info] level 2022-02-15T14:11:45Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:45Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:45Z [INFO][UDM][CFG] config version [1.0.1] 2022-02-15T14:11:45Z [INFO][UDM][Init] UDM Config Info: Version[1.0.1] Description[UDM initial local configuration] 2022-02-15T14:11:45Z [INFO][UDM][Init] Server started 2022-02-15T14:11:45Z [INFO][UDM][Util] udmconfig Info: Version[1.0.1] Description[UDM initial local configuration] 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:45Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:45Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/f0c29cf7-9a55-4363-84dc-31d1f5bd235e 2022-02-15T14:11:45Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/f0c29cf7-9a55-4363-84dc-31d1f5bd235e | nssf 2022-02-15T14:11:46Z [INFO][NSSF][App] NSSF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:10:57Z commit hash: 2183c752 commit time: 2021-07-30T09:01:26Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:46Z [INFO][NSSF][Init] NSSF Log level is set to [info] level 2022-02-15T14:11:46Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:46Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:46Z [INFO][NSSF][CFG] config version [1.0.0] 2022-02-15T14:11:46Z [INFO][NSSF][Init] Server started 2022-02-15T14:11:46Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:46Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:46Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:46Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/1528b0f9-ff89-4d8a-9df6-667d7ba39bf8 2022-02-15T14:11:46Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/1528b0f9-ff89-4d8a-9df6-667d7ba39bf8 | ausf 2022-02-15T14:11:46Z [INFO][AUSF][App] AUSF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:08:52Z commit hash: b2dcd719 commit time: 2021-11-06T18:45:22Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:46Z [INFO][AUSF][Init] AUSF Log level is set to [info] level 2022-02-15T14:11:46Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:46Z [INFO][LIB][OAPI] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][OAPI] set report call : false 2022-02-15T14:11:46Z [INFO][AUSF][CFG] config version [1.0.0] 2022-02-15T14:11:46Z [INFO][AUSF][Init] Server started 2022-02-15T14:11:46Z [INFO][AUSF][Init] ausfconfig Info: Version[1.0.0] Description[AUSF initial local configuration] ausf context = &{{{0 0} {} map[] 0} {{0 0} {} map[] 0} bf5d7ed5-5af4-46b2-adc5-cbe769372812 ausfGroup001 8000 127.0.0.9 127.0.0.9 http://127.0.0.9:8000 http http://127.0.0.10:8000 map[nausf-auth:{bf5d7ed5-5af4-46b2-adc5-cbe769372812 nausf-auth 0xc00000cd20 http REGISTERED 0xc00000cd08 [] [] [] 0 0 0 }] [{208 93} {123 45}] 0xc0002c9180 false} 2022-02-15T14:11:46Z [INFO][NRF][MGMT] Handle NFRegisterRequest 2022-02-15T14:11:46Z [INFO][NRF][MGMT] urilist update 2022-02-15T14:11:46Z [INFO][NRF][MGMT] Create NF Profile 2022-02-15T14:11:46Z [INFO][NRF][MGMT] Location header: http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/bf5d7ed5-5af4-46b2-adc5-cbe769372812 2022-02-15T14:11:46Z [INFO][NRF][GIN] | 201 | 127.0.0.1 | PUT | /nnrf-nfm/v1/nf-instances/bf5d7ed5-5af4-46b2-adc5-cbe769372812 | 2022-02-15T14:11:46Z [INFO][N3IWF][App] n3iwf 2022-02-15T14:11:46Z [INFO][N3IWF][App] N3IWF version: free5GC version: v3.0.6-10-gfa56062 build time: 2022-02-09T13:11:19Z commit hash: c856d5f2 commit time: 2021-10-22T11:59:18Z go version: go1.17.6 linux/amd64 2022-02-15T14:11:46Z [INFO][N3IWF][Init] N3IWF Log level is set to [debug] level 2022-02-15T14:11:46Z [INFO][LIB][NGAP] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][NGAP] set report call : false 2022-02-15T14:11:46Z [INFO][LIB][Aper] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][Aper] set report call : false 2022-02-15T14:11:46Z [INFO][LIB][Path] set log level : info 2022-02-15T14:11:46Z [INFO][LIB][Path] set report call : false 2022-02-15T14:11:46Z [INFO][N3IWF][CFG] config version [1.0.0] 2022-02-15T14:11:46Z [INFO][N3IWF][Init] Server started 2022-02-15T14:11:46Z [WARN][N3IWF][Context] No private key file path specified, load default key file... 2022-02-15T14:11:46Z [WARN][N3IWF][Context] Parse PKCS8 private key failed: x509: failed to parse private key (use ParsePKCS1PrivateKey instead for this key format) 2022-02-15T14:11:46Z [INFO][N3IWF][Context] Parse using PKCS1... 2022-02-15T14:11:46Z [WARN][N3IWF][Context] No certificate authority file path specified, load default CA certificate... 2022-02-15T14:11:46Z [WARN][N3IWF][Context] No certificate file path specified, load default certificate... 2022-02-15T14:11:46Z [INFO][AMF][NGAP] [AMF] SCTP Accept from: 192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795 2022-02-15T14:11:46Z [INFO][N3IWF][Init] NGAP service running. 2022-02-15T14:11:46Z [INFO][N3IWF][Init] NAS TCP server successfully started. 2022-02-15T14:11:46Z [INFO][N3IWF][Init] Listening NWu user plane traffic 2022-02-15T14:11:46Z [INFO][N3IWF][Init] IKE service running. 2022-02-15T14:11:46Z [INFO][N3IWF][Init] N3IWF running... 2022-02-15T14:11:46Z [INFO][N3IWF][NGAP] [N3IWF] Send NG Setup Request 2022-02-15T14:11:46Z [INFO][AMF][NGAP] Create a new NG connection for: 192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795 2022-02-15T14:11:46Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle NG Setup request 2022-02-15T14:11:46Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Send NG-Setup response 2022-02-15T14:11:46Z [INFO][N3IWF][NGAP] [N3IWF] Handle NG Setup Response 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [SecurityAssociation] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [KeyExchange] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Nonce] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Handle IKE_SA_INIT 2022-02-15T14:11:57Z [WARN][N3IWF][IKE] The Diffie-Hellman group defined in key exchange payload not matches the one in chosen proposal 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [SecurityAssociation] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [KeyExchange] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Nonce] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Handle IKE_SA_INIT 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] ====== IKE Security Association Info ===== 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] Remote SPI: b34e4e13434d05eb 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] Local SPI: 25617f1a03c26d35 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] Encryption Algorithm: 12 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] SK_ei: 564fe98e8cd386bb8625d42802b39872 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] SK_er: cfa2e345aa892033041cb9aad41333e4 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] Integrity Algorithm: 2 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] SK_ai: d852a6a489c06e537ab5b4922f6a28bb63f104ed 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] SK_ar: c4c051aae627dd8f0b4bee1096fe36ba591d297a 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] SK_pi: 7a8d7993cc730fef518472755541d2e004dc723f 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] SK_pr: 4f083f6c5fca47179f821275e49d2fad6c3383c8 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [KeyExchange] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Nonce] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [KeyExchange] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Nonce] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Identification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [KeyExchange] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Nonce] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Handle IKE_AUTH 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Identification] unmarshal(): Start unmarshalling received bytes2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Configuration] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [SecurityAssociation] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [TrafficSelector] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [TrafficSelector] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Ecoding initiator for later IKE authentication 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Identification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Parsing security association 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Received traffic selector initiator from UE 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Received traffic selector initiator from UE 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Identification] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Certificate] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Authentication] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP][Expanded] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Handle IKE_AUTH 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP][Expanded] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [DEBU][N3IWF][IKE] parameterValue: [2 248 57 202 254 0] 2022-02-15T14:11:57Z [INFO][N3IWF][NGAP] [N3IWF] Send Initial UE Message 2022-02-15T14:11:57Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle Initial UE Message 2022-02-15T14:11:57Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Handle Registration Request 2022-02-15T14:11:57Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Authentication procedure 2022-02-15T14:11:57Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:57Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=AUSF | 2022-02-15T14:11:57Z [INFO][AUSF][UeAuthPost] HandleUeAuthPostRequest 2022-02-15T14:11:57Z [INFO][AUSF][UeAuthPost] Serving network authorized 2022-02-15T14:11:57Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:57Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AUSF&service-names=nudm-ueau&target-nf-type=UDM | 2022-02-15T14:11:57Z [INFO][UDM][UEAU] Handle GenerateAuthDataRequest 2022-02-15T14:11:57Z [INFO][LIB][3GPP] suciPart: [suci 0 208 93 0 0 0 00007487] 2022-02-15T14:11:57Z [INFO][LIB][3GPP] scheme 0 2022-02-15T14:11:57Z [INFO][LIB][3GPP] SUPI type is IMSI http://127.0.0.10:8000 2022-02-15T14:11:57Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:57Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=UDM&target-nf-type=UDR | 2022-02-15T14:11:57Z [INFO][UDR][DRepo] Handle QueryAuthSubsData 2022-02-15T14:11:57Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/authentication-data/authentication-subscription | 2022-02-15T14:11:57Z [INFO][UDR][DRepo] Handle ModifyAuthentication 2022-02-15T14:11:57Z [INFO][UDR][GIN] | 204 | 127.0.0.1 | PATCH | /nudr-dr/v1/subscription-data/imsi-2089300007487/authentication-data/authentication-subscription | AUTN = 030c02164b7080008ebfd596866e8298 2022-02-15T14:11:57Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | POST | /nudm-ueau/v1/suci-0-208-93-0-0-0-00007487/security-information/generate-auth-data | 2022-02-15T14:11:57Z [INFO][AUSF][UeAuthPost] Add SuciSupiPair (suci-0-208-93-0-0-0-00007487, imsi-2089300007487) to map. 2022-02-15T14:11:57Z [INFO][AUSF][UeAuthPost] Use 5G AKA auth method 2022-02-15T14:11:57Z [INFO][AUSF][5gAkaAuth] XresStar = 6636346663353236396366373135623663646533646364653232626633666363 2022-02-15T14:11:57Z [INFO][AUSF][GIN] | 201 | 127.0.0.1 | POST | /nausf-auth/v1/ue-authentications | 2022-02-15T14:11:57Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Send Authentication Request 2022-02-15T14:11:57Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-02-15T14:11:57Z [INFO][N3IWF][NGAP] [N3IWF] Handle Downlink NAS Transport 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP][Expanded] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Handle IKE_AUTH 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][IKE] [EAP][Expanded] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:57Z [INFO][N3IWF][NGAP] [N3IWF] Send Uplink NAS Transport 2022-02-15T14:11:57Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle Uplink Nas Transport 2022-02-15T14:11:57Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:11:57Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Handle Authentication Response 2022-02-15T14:11:57Z [INFO][AUSF][5gAkaAuth] Auth5gAkaComfirmRequest 2022-02-15T14:11:57Z [INFO][AUSF][5gAkaAuth] res: 6636346663353236396366373135623663646533646364653232626633666363 Xres: 6636346663353236396366373135623663646533646364653232626633666363 2022-02-15T14:11:57Z [INFO][AUSF][5gAkaAuth] 5G AKA confirmation succeeded 2022-02-15T14:11:57Z [INFO][UDM][UEAU] Handle ConfirmAuthDataRequest 2022-02-15T14:11:57Z [INFO][UDR][DRepo] Handle CreateAuthenticationStatus 2022-02-15T14:11:57Z [INFO][UDR][GIN] | 204 | 127.0.0.1 | PUT | /nudr-dr/v1/subscription-data/imsi-2089300007487/authentication-data/authentication-status | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 201 | 127.0.0.1 | POST | /nudm-ueau/v1/imsi-2089300007487/auth-events | 2022-02-15T14:11:58Z [INFO][AUSF][GIN] | 200 | 127.0.0.1 | PUT | /nausf-auth/v1/ue-authentications/suci-0-208-93-0-0-0-00007487/5g-aka-confirmation | 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Send Security Mode Command 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Handle Downlink NAS Transport 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [EAP] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [EAP][Expanded] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Handle IKE_AUTH 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [EAP] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [EAP][Expanded] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Send Uplink NAS Transport 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle Uplink Nas Transport 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle Security Mode Complete 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle InitialRegistration 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-2089300007487&target-nf-type=UDM | 2022-02-15T14:11:58Z [INFO][UDM][SDM] Handle GetNssai 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle QueryAmData 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/am-data?supported-features= | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/nssai?plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-2089300007487&target-nf-type=UDM | 2022-02-15T14:11:58Z [INFO][UDM][UECM] Handle RegisterAmfNon3gppAccessRequest 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle CreateAmfContextNon3gpp 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 204 | 127.0.0.1 | PUT | /nudr-dr/v1/subscription-data/imsi-2089300007487/context-data/amf-non-3gpp-access | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 201 | 127.0.0.1 | PUT | /nudm-uecm/v1/imsi-2089300007487/registrations/amf-non-3gpp-access | 2022-02-15T14:11:58Z [INFO][UDM][SDM] Handle GetAmData 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle QueryAmData 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/am-data?supported-features=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/am-data?plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:11:58Z [INFO][UDM][SDM] Handle GetSmfSelectData 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle QuerySmfSelectData 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/smf-selection-subscription-data?supported-features= | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/smf-select-data?plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:11:58Z [INFO][UDM][SDM] Handle GetUeContextInSmfData 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle QuerySmfRegList 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/context-data/smf-registrations?supported-features= | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/ue-context-in-smf-data | 2022-02-15T14:11:58Z [INFO][UDM][SDM] Handle Subscribe 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle CreateSdmSubscriptions 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 201 | 127.0.0.1 | POST | /nudr-dr/v1/subscription-data/imsi-2089300007487/context-data/sdm-subscriptions | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 201 | 127.0.0.1 | POST | /nudm-sdm/v1/imsi-2089300007487/sdm-subscriptions | 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?preferred-locality=area1&requester-nf-type=AMF&supi=imsi-2089300007487&target-nf-type=PCF | 2022-02-15T14:11:58Z [INFO][PCF][Ampolicy] Handle AM Policy Create Request 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=PCF&target-nf-type=UDR | 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle PolicyDataUesUeIdAmDataGet 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/policy-data/ues/imsi-2089300007487/am-data | 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?guami=%7B%22plmnId%22%3A%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D%2C%22amfId%22%3A%22cafe00%22%7D&requester-nf-type=PCF&target-nf-type=AMF | 2022-02-15T14:11:58Z [INFO][AMF][Comm] Handle AMF Status Change Subscribe Request 2022-02-15T14:11:58Z [INFO][AMF][Comm] new AMF Status Subscription[1] 2022-02-15T14:11:58Z [INFO][AMF][GIN] | 201 | 127.0.0.1 | POST | /namf-comm/v1/subscriptions | 2022-02-15T14:11:58Z [INFO][PCF][GIN] | 201 | 127.0.0.1 | POST | /npcf-am-policy-control/v1/policies | 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Send Initial Context Setup Request 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Handle Initial Context Setup Request 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [EAP] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Handle IKE_AUTH 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Authentication] unmarshal(): Start unmarshalling received bytes2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Configuration] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:11:58Z [WARN][N3IWF][IKE] Receive other type of configuration request: 3 2022-02-15T14:11:58Z [WARN][N3IWF][IKE] Receive other type of configuration request: 8 2022-02-15T14:11:58Z [WARN][N3IWF][IKE] Receive other type of configuration request: 10 2022-02-15T14:11:58Z [WARN][N3IWF][IKE] Receive other type of configuration request: 20 2022-02-15T14:11:58Z [WARN][N3IWF][IKE] Receive other type of configuration request: 21 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] ====== IPSec/Child SA: Initiator To Responder ===== 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec SPI: 00000000789fa07c 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Encryption Algorithm: 12 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Encryption Key: faf3923e534bba01b2c54c0e51621af3f0a9430bbc5c744e2a51db4bce4b9d77 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Integrity Algorithm: 0 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Integrity Key: 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] ====== IPSec/Child SA: Responder To Initiator ===== 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec SPI: 00000000789fa07c 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Encryption Algorithm: 12 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Encryption Key: fcee078b3cb44805f85aee33e51b796ebdbe95df322ea670042fc36a9ba67da6 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Integrity Algorithm: 0 2022-02-15T14:11:58Z [DEBU][N3IWF][IKE] IPSec Integrity Key: 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Authentication] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Configuration] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:11:58Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Send Initial Context Setup Response 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle Initial Context Setup Response 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Handle Downlink NAS Transport 2022-02-15T14:11:58Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Send Uplink NAS Transport 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle Uplink Nas Transport 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle Registration Complete 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Send Uplink NAS Transport 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle Uplink Nas Transport 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle UL NAS Transport2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Transport 5GSM Message to SMF 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Select SMF [snssai: {Sst:1 Sd:010203}, dnn: internet] 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=NSSF | 2022-02-15T14:11:58Z [INFO][NSSF][NsSelect] Handle NSSelectionGet 2022-02-15T14:11:58Z [INFO][NSSF][GIN] | 200 | 127.0.0.1 | GET | /nnssf-nsselection/v1/network-slice-information?nf-id=8e6c1a04-5392-4eb9-bb94-4409289fcd83&nf-type=AMF&slice-info-request-for-pdu-session=%7B%22sNssai%22%3A%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D%2C%22roamingIndication%22%3A%22NON_ROAMING%22%7D | 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?dnn=internet&preferred-locality=area1&requester-nf-type=AMF&service-names=nsmf-pdusession&snssais=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D&target-nf-type=SMF&target-plmn-list=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:11:58Z [INFO][SMF][PduSess] Receive Create SM Context Request 2022-02-15T14:11:58Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-type=UDM | 2022-02-15T14:11:58Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2022-02-15T14:11:58Z [INFO][SMF][CTX] Allocated UE IP address: 60.60.0.1 2022-02-15T14:11:58Z [INFO][SMF][CTX] Selected UPF: UPF 2022-02-15T14:11:58Z [INFO][SMF][PduSess] UE[imsi-2089300007487] PDUSessionID[5] IP[60.60.0.1] 2022-02-15T14:11:58Z [INFO][UDM][SDM] Handle GetSmData 2022-02-15T14:11:58Z [INFO][UDM][SDM] getSmDataProcedure: SUPI[imsi-2089300007487] PLMNID[20893] DNN[internet] SNssai[{"sst":1,"sd":"010203"}] 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle QuerySmData 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/sm-data?single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:11:58Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/sm-data?dnn=internet&plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D&single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:11:58Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2022-02-15T14:11:58Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc0002d4e80] 2022-02-15T14:11:58Z [INFO][SMF][GSM] Protocol Configuration Options 2022-02-15T14:11:58Z [INFO][SMF][GSM] &{[0xc0002d4e80]} 2022-02-15T14:11:58Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-2089300007487] PDUSessionID[5] 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?preferred-locality=area1&requester-nf-type=SMF&target-nf-type=PCF | 2022-02-15T14:11:58Z [INFO][PCF][SMpolicy] Handle CreateSmPolicy 2022-02-15T14:11:58Z [INFO][UDR][DRepo] Handle PolicyDataUesUeIdSmDataGet 2022-02-15T14:11:58Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/policy-data/ues/imsi-2089300007487/sm-data?dnn=internet&snssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:11:58Z [INFO][PCF][GIN] | 201 | 127.0.0.1 | POST | /npcf-smpolicycontrol/v1/sm-policies | 2022-02-15T14:11:58Z [INFO][SMF][PduSess] SUPI[imsi-2089300007487] has no pre-config route 2022-02-15T14:11:58Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:11:58Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-instance-id=8e6c1a04-5392-4eb9-bb94-4409289fcd83&target-nf-type=AMF | 2022-02-15T14:11:58Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2022-02-15T14:11:58Z [INFO][SMF][GIN] | 201 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts | 2022-02-15T14:11:58Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] create smContext[pduSessionID: 5] Success 2022-02-15T14:11:58Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request 2022-02-15T14:11:58Z [INFO][UPF][Util] [PFCP] Session Establishment Response 2022-02-15T14:11:58Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse &{1000 Kbps 1000 Kbps} 2022-02-15T14:11:58Z [INFO][LIB][PFCP] Remove Request Transaction [2] 2022-02-15T14:11:58Z [INFO][AMF][Producer] Handle N1N2 Message Transfer Request 2022-02-15T14:11:58Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795][AMF_UE_NGAP_ID:1] Send PDU Session Resource Setup Request 2022-02-15T14:11:58Z [INFO][AMF][GIN] | 200 | 127.0.0.1 | POST | /namf-comm/v1/ue-contexts/imsi-2089300007487/n1-n2-messages | 2022-02-15T14:11:58Z [INFO][N3IWF][NGAP] [N3IWF] Handle PDU Session Resource Setup Request 2022-02-15T14:12:03Z [ERRO][N3IWF][GTP] Dial to UPF failed: read udp 192.168.57.103:2152: i/o timeout 2022-02-15T14:12:03Z [ERRO][N3IWF][NGAP] Setup GTP connection with UPF failed: Dial failed 2022-02-15T14:12:03Z [INFO][N3IWF][NGAP] [N3IWF] Send PDU Session Resource Setup Response 2022-02-15T14:12:03Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:35795] Handle PDU Session Resource Setup Response 2022-02-15T14:12:03Z [INFO][SMF][PduSess] Receive Update SM Context Request 2022-02-15T14:12:03Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-02-15T14:12:03Z [ERRO][SMF][PduSess] Handle PDUSessionResourceSetupResponseTransfer failed: sequence truncated 2022-02-15T14:12:03Z [WARN][SMF][PduSess] SM Context State [Active] shouldn't be here 2022-02-15T14:12:03Z [INFO][SMF][GIN] | 200 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:a37fb0a7-bee8-4202-baff-2196f62f6571/modify |

From: Fabricio @.> Sent: Tuesday, February 15, 2022 15:09 To: fasferraz/NWu-Non3GPP-5GC @.> Cc: Aravind KANNAN @.>; Author @.> Subject: Re: [fasferraz/NWu-Non3GPP-5GC] PDUSessionResourceSetupResponseTransfer failed: sequence truncated (Issue #3)

Hi, Those messages in the free5gc log are after the N3IWF received the PDU Session Establishment Request from the UE. It looks something is failing in the free5gc with the UPF. The userplane SA child is not being created...

Can you increase the log level do debug?

In version 3.0.6 the free5GC does not send yet the PDU Session Establishment Accepted to the UE. If you want to add this you need to modify NFs/n3iwf/ngap/handler/handler.go file and add some code: @.***https://github.com/fasferraz/n3iwf/commit/7226b0e1dc43fdd617a7f5f334443268ae9dbc88, and rebuild the N3IWF again (make n3iwf) Nevertheless, this will only happen if everything is ok with session creation, which is not the case with your logs, since you have some internal errors...

This is my log:

2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810] Handle Uplink Nas Transport 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle Registration Complete 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810] Handle Uplink Nas Transport 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 0) 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle UL NAS Transport 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Transport 5GSM Message to SMF 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Select SMF [snssai: {Sst:1 Sd:010203}, dnn: internet] 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=NSSF | 2022-02-15T14:03:54Z [INFO][NSSF][NsSelect] Handle NSSelectionGet 2022-02-15T14:03:54Z [INFO][NSSF][GIN] | 200 | 127.0.0.1 | GET | /nnssf-nsselection/v1/network-slice-information?nf-id=f78285c9-0672-4a0d-b784-a5a2f0e3daae&nf-type=AMF&slice-info-request-for-pdu-session=%7B%22sNssai%22%3A%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D%2C%22roamingIndication%22%3A%22NON_ROAMING%22%7D | 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?dnn=internet&preferred-locality=area1&requester-nf-type=AMF&service-names=nsmf-pdusession&snssais=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D&target-nf-type=SMF&target-plmn-list=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D | 2022-02-15T14:03:54Z [INFO][SMF][PduSess] Recieve Create SM Context Request 2022-02-15T14:03:54Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-type=UDM | 2022-02-15T14:03:54Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2022-02-15T14:03:54Z [INFO][SMF][CTX] Allocated UE IP address: 60.60.0.1 2022-02-15T14:03:54Z [INFO][SMF][CTX] Selected UPF: UPF 2022-02-15T14:03:54Z [INFO][SMF][PduSess] UE[imsi-2089300007487] PDUSessionID[5] IP[60.60.0.1] 2022-02-15T14:03:54Z [INFO][UDM][SDM] Handle GetSmData 2022-02-15T14:03:54Z [INFO][UDM][SDM] getSmDataProcedure: SUPI[imsi-2089300007487] PLMNID[20893] DNN[internet] SNssai[{"sst":1,"sd":"010203"}] 2022-02-15T14:03:54Z [INFO][UDR][DRepo] Handle QuerySmData 2022-02-15T14:03:54Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/sm-data?single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:03:54Z [INFO][UDM][GIN] | 200 | 127.0.0.1 | GET | /nudm-sdm/v1/imsi-2089300007487/sm-data?dnn=internet&plmn-id=20893&single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:03:54Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2022-02-15T14:03:54Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc00000cae0] 2022-02-15T14:03:54Z [INFO][SMF][GSM] Protocol Configuration Options 2022-02-15T14:03:54Z [INFO][SMF][GSM] &{[0xc00000cae0]} 2022-02-15T14:03:54Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-2089300007487] PDUSessionID[5] 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-type=PCF | 2022-02-15T14:03:54Z [INFO][PCF][SMpolicy] Handle CreateSmPolicy 2022-02-15T14:03:54Z [INFO][UDR][DRepo] Handle PolicyDataUesUeIdSmDataGet 2022-02-15T14:03:54Z [INFO][UDR][GIN] | 200 | 127.0.0.1 | GET | /nudr-dr/v1/policy-data/ues/imsi-2089300007487/sm-data?dnn=internet&snssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D | 2022-02-15T14:03:54Z [INFO][PCF][GIN] | 201 | 127.0.0.1 | POST | /npcf-smpolicycontrol/v1/sm-policies | 2022-02-15T14:03:54Z [INFO][SMF][PduSess] SUPI[imsi-2089300007487] has no pre-config route 2022-02-15T14:03:54Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2022-02-15T14:03:54Z [INFO][NRF][GIN] | 200 | 127.0.0.1 | GET | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-instance-id=f78285c9-0672-4a0d-b784-a5a2f0e3daae&target-nf-type=AMF | 2022-02-15T14:03:54Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2022-02-15T14:03:54Z [INFO][SMF][GIN] | 201 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts | 2022-02-15T14:03:54Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] create smContext[pduSessionID: 5] Success 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Session Establishment Response 2022-02-15T14:03:54Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse &{1000 Kbps 1000 Kbps} 2022-02-15T14:03:54Z [INFO][LIB][PFCP] Remove Request Transaction [2] 2022-02-15T14:03:54Z [INFO][AMF][Producer] Handle N1N2 Message Transfer Request 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810][AMF_UE_NGAP_ID:1] Send PDU Session Resource Setup Request 2022-02-15T14:03:54Z [INFO][AMF][GIN] | 200 | 127.0.0.1 | POST | /namf-comm/v1/ue-contexts/imsi-2089300007487/n1-n2-messages | 2022-02-15T14:03:54Z [INFO][N3IWF][NGAP] [N3IWF] Handle PDU Session Resource Setup Request 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Nonce] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Decoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Handle CREATE_CHILD_SA 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] Decoding IKE payloads 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [SecurityAssociation] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [Nonce] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][IKE] [TrafficSelector] unmarshal(): Start unmarshalling received bytes 2022-02-15T14:03:54Z [INFO][N3IWF][NGAP] [N3IWF] Send PDU Session Resource Setup Response 2022-02-15T14:03:54Z [INFO][AMF][NGAP][172.16.168.131/10.0.0.1/172.16.62.131/172.16.63.11:43810] Handle PDU Session Resource Setup Response 2022-02-15T14:03:54Z [INFO][SMF][PduSess] Recieve Update SM Context Request 2022-02-15T14:03:54Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Handle PFCP session modification request 2022-02-15T14:03:54Z [INFO][UPF][Util] [PFCP] Session Modification Response 2022-02-15T14:03:54Z [INFO][LIB][PFCP] Remove Request Transaction [3] 2022-02-15T14:03:54Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse 2022-02-15T14:03:54Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept 2022-02-15T14:03:54Z [INFO][SMF][PFCP] PFCP Session Modification Success[1] 2022-02-15T14:03:54Z [INFO][SMF][GIN] | 200 | 127.0.0.1 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:5d686404-1943-47f8-b83e-d6e66b0cff6a/modify |

— Reply to this email directly, view it on GitHubhttps://github.com/fasferraz/NWu-Non3GPP-5GC/issues/3#issuecomment-1040317249, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AV3TEBPM63TB6USUSY53C2TU3JNAHANCNFSM5OOOR2GQ. Triage notifications on the go with GitHub Mobile for iOShttps://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Androidhttps://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub. You are receiving this because you authored the thread.Message ID: @.***>

fasferraz commented 2 years ago

Hi,

Your first errors are these lines:

2022-02-15T14:12:03Z [ERRO][N3IWF][GTP] Dial to UPF failed: read udp 192.168.57.103:2152: i/o timeout 2022-02-15T14:12:03Z [ERRO][N3IWF][NGAP] Setup GTP connection with UPF failed: Dial failed

Are you able to test your setup with UERANSIM successfully? It seems there is a timeout when trying to reach 192.168.57.102 in gtp-u port (2152) What is the address you are using for GTP-U in n3uwf and in ufp? They should be different since they need to open the same port. can you ping one address from the other? can you print your n3iwfcfg.yaml and upfcfg.yaml?

Aravindchockaiaahkannan commented 2 years ago

I can test it with UERANSIM successfully. The addresses in the N3IWF and UPF are different. After reading your questions, i think i might have gone wrong in creating the interface for the N3IWF GTP. In your setup example i can see that you have an interface named vmnet0. i created a bridged adapter and gave the IP of 192.168.57.103. This might be wrong ?

I am printing my n3iwfcfg.yaml and upfcfg.yaml down below. And thanks for replies. n3iwfcfg.yaml : info: version: 1.0.0 description: N3IWF initial local configuration

configuration: N3IWFInformation: GlobalN3IWFID: # ID used to globally identify an N3IWF PLMNID: # Public Land Mobile Network ID, = MCC: # Mobile Country Code (3 digits string, digit: 0~9) 208 MNC: # Mobile Network Code (2 or 3 digits string, digit: 0~9) 93 N3IWFID: # ID used to identify an N3IWF in PLMN (uinteger, range: 0~65535) 135 Name: # The name of this N3IWF free5GC_N3IWF SupportedTAList: # Tracking Area supported by this N3IWF

the kind of log output

debugLevel: how detailed to output, value: trace, debug, info, warn, error, fatal, panic

ReportCaller: enable the caller report or not, value: true or false

logger: N3IWF: # The default log level is DEBUG to print SA keys. Please change it to INFO when deployed. debugLevel: debug ReportCaller: false NGAP: debugLevel: info ReportCaller: false Aper: debugLevel: info ReportCaller: false PathUtil: debugLevel: info ReportCaller: false

upfcfg.yaml:

info: version: 1.0.0 description: UPF configuration

configuration:

the kind of log output

# debugLevel: how detailed to output, value: trace, debug, info, warn, error, fatal, panic
# ReportCaller: enable the caller report or not, value: true or false

debugLevel: info ReportCaller: false

packetBufferHoldTime should be longer than Paging retry-out time of AMF.

unit: seconds

packetBufferHoldTime: 30

The IP list of the N4 interface on this UPF (Can't set to 0.0.0.0)

pfcp:

fasferraz commented 2 years ago

Hi, Can you change the bridge interface to host-only (for example), and try again?

If it doesn't work, can you do a tcpdump of all interfaces in the freee5gc VM, and send it to me? my email is in my profile.

Aravindchockaiaahkannan commented 2 years ago

Hi,

i tried changing the adapter, UE is not crossing stage 5.

Signaling SA CHILD created. Establishing TCP session towards NAS...

Cannot create namespace file "/run/netns/tcp_socket_signalling": File exists cmd: ip netns exec tcp_socket_signalling ip link set dev tun2 up cmd: ip netns exec tcp_socket_signalling ip addr add 10.0.0.132/32 dev tun2 cmd: ip netns exec tcp_socket_signalling route add -net 0.0.0.0/0 gw 10.0.0.132 Tcp connection to NAS timeouted. Ending TCP Process. Exiting TCP process. Process terminated.

in the core,

2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Authentication] unmarshal(): Start unmarshalling received bytes2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Configuration] unmarshal(): Start unmarshalling received bytes 2022-02-16T09:35:50Z [WARN][N3IWF][IKE] Receive other type of configuration request: 3 2022-02-16T09:35:50Z [WARN][N3IWF][IKE] Receive other type of configuration request: 8 2022-02-16T09:35:50Z [WARN][N3IWF][IKE] Receive other type of configuration request: 10 2022-02-16T09:35:50Z [WARN][N3IWF][IKE] Receive other type of configuration request: 20 2022-02-16T09:35:50Z [WARN][N3IWF][IKE] Receive other type of configuration request: 21 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] ====== IPSec/Child SA: Initiator To Responder ===== 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec SPI: 00000000e77450a5 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Encryption Algorithm: 12 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Encryption Key: 5bc5260298e8fc99340bd0f6d007f6fad91edec76d8d4d3a98d827678e38930e 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Integrity Algorithm: 0 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Integrity Key: 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] ====== IPSec/Child SA: Responder To Initiator ===== 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec SPI: 00000000e77450a5 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Encryption Algorithm: 12 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Encryption Key: 8bbbeafee97f842cf65139ecca8bfecb6cc270e0f7bda2cb15dd8da706e96f17 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Integrity Algorithm: 0 2022-02-16T09:35:50Z [DEBU][N3IWF][IKE] IPSec Integrity Key: 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Authentication] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Configuration] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [SecurityAssociation] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [TrafficSelector] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Notification] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] Encoding IKE message 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] Encoding IKE payloads 2022-02-16T09:35:50Z [INFO][N3IWF][IKE] [Encrypted] marshal(): Start marshalling 2022-02-16T09:35:50Z [INFO][N3IWF][NGAP] [N3IWF] Send Initial Context Setup Response 2022-02-16T09:35:50Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:43491] Handle Initial Context Setup Response 2022-02-16T09:35:50Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:43491][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-02-16T09:35:50Z [INFO][N3IWF][NGAP] [N3IWF] Handle Downlink NAS Transport 2022-02-16T09:35:50Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-16T09:35:51Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-16T09:35:51Z [WARN][N3IWF][NGAP] No connection found for UE to send NAS message. This message will be cached in N3IWF

fasferraz commented 2 years ago

It seems you had a previous process running in the emulator VM (the namespace already existed?). Can you check? Or reload the emulator VM, and try again.

Aravindchockaiaahkannan commented 2 years ago

restarting the VM cleared the issue, but the UE state remains at 6.

the core:

2022-02-16T10:01:10Z [INFO][N3IWF][NGAP] [N3IWF] Handle Downlink NAS Transport 2022-02-16T10:01:10Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-16T10:01:11Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-16T10:01:11Z [WARN][N3IWF][NGAP] No connection found for UE to send NAS message. This message will be cached in N3IWF

i tried it with host only adapter

fasferraz commented 2 years ago

You only changed interface 192.168.57.103 to host-only, right? Can you change it to NAT and try? If you revert it back to bridge you stop at stage 7?

That interface is the N3 interface of N3IWF used to communicate with UPF, which has Ip 127.0.0.8.

I'm not an expert in free5gc... the only difference i see between your setup and mine is that you use the same IP for ike and for AMF - 192.168.56.103, but that could be possible since ike and ngap use different ports and protocols...

Aravindchockaiaahkannan commented 2 years ago

If i revert back to bridge adapter, i cannot go stage 7. the UE stops at stage 6.

Aravindchockaiaahkannan commented 2 years ago

I tried with the third network interface off, and still my UE stops at stage 6. so i think, network interface must be the problem.

What kind of interface is vmnet0 in your setup ?

Thanks

fasferraz commented 2 years ago

It's in the drawing, in wiki. It's custom: vmnet0

Why don't you try to add a third interface as custom (vmnet0), and configure another network there (192.168.58.103 for example) and use this IP as the GTPIP in the n3iwfcfg.yaml?

Aravindchockaiaahkannan commented 2 years ago

Hi, I tried with various combinations, nothing seems to cross UE in stage 6. but in the free5gc log below you can see the created third interface was successfully added to the core below. The ip of the new interface for gtp ip in n3iwfcfg is 192.168.57.103. and ng response was successful. yet UE remains at state 6 saying "Tcp connection to NAS timeouted. Ending TCP Process. Exiting TCP process. Process terminated."

Free5gc log focused on 192.168.57.103 (Newly created interface): 2022-02-16T15:18:47Z [INFO][N3IWF][Context] Parse using PKCS1... 2022-02-16T15:18:47Z [WARN][N3IWF][Context] No certificate authority file path specified, load default CA certificate... 2022-02-16T15:18:47Z [WARN][N3IWF][Context] No certificate file path specified, load default certificate... 2022-02-16T15:18:47Z [INFO][AMF][NGAP] [AMF] SCTP Accept from: 192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:44876 2022-02-16T15:18:47Z [INFO][N3IWF][Init] NGAP service running. 2022-02-16T15:18:47Z [INFO][N3IWF][Init] NAS TCP server successfully started. 2022-02-16T15:18:47Z [INFO][N3IWF][NGAP] [N3IWF] Send NG Setup Request 2022-02-16T15:18:47Z [INFO][AMF][NGAP] Create a new NG connection for: 192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:44876 2022-02-16T15:18:47Z [INFO][N3IWF][Init] Listening NWu user plane traffic 2022-02-16T15:18:47Z [INFO][N3IWF][Init] IKE service running. 2022-02-16T15:18:47Z [INFO][N3IWF][Init] N3IWF running...

Aravindchockaiaahkannan commented 2 years ago

I'm printing the routing table if it helps, of both the machines.

free5gc: Kernel IP routing table Destination Gateway Genmask Flags Metric Ref Use Iface 0.0.0.0 10.0.2.2 0.0.0.0 UG 100 0 0 enp0s3 10.0.0.0 0.0.0.0 255.255.255.0 U 0 0 0 ipsec0 10.0.2.0 0.0.0.0 255.255.255.0 U 0 0 0 enp0s3 10.0.2.2 0.0.0.0 255.255.255.255 UH 100 0 0 enp0s3 192.168.56.0 0.0.0.0 255.255.255.0 U 0 0 0 enp0s8 192.168.57.0 0.0.0.0 255.255.255.0 U 0 0 0 enp0s10

UE Kernel IP routing table Destination Gateway Genmask Flags Metric Ref Use Iface 0.0.0.0 10.0.2.2 0.0.0.0 UG 100 0 0 enp0s3 10.0.2.0 0.0.0.0 255.255.255.0 U 0 0 0 enp0s3 10.0.2.2 0.0.0.0 255.255.255.255 UH 100 0 0 enp0s3 192.168.56.0 0.0.0.0 255.255.255.0 U 0 0 0 enp0s8

Aravindchockaiaahkannan commented 2 years ago

At the same time in the UE, i can see this, that it is trying to create a tun2 but it is not creating tun2. might this be the error log from the core ? correct me if am wrong

UE: Signaling SA CHILD created. Establishing TCP session towards NAS... cmd: ip netns exec tcp_socket_signalling ip link set dev tun2 up cmd: ip netns exec tcp_socket_signalling ip addr add 10.0.0.243/32 dev tun2 cmd: ip netns exec tcp_socket_signalling route add -net 0.0.0.0/0 gw 10.0.0.243 Tcp connection to NAS timeouted. Ending TCP Process. Exiting TCP process. Process terminated.

Free5gc:

itial Context Setup Response 2022-02-16T15:48:51Z [INFO][AMF][NGAP][192.168.56.103/10.0.2.15/192.168.57.103/10.0.0.1:49821][AMF_UE_NGAP_ID:3] Send Downlink Nas Transport 2022-02-16T15:48:51Z [INFO][N3IWF][NGAP] [N3IWF] Handle Downlink NAS Transport 2022-02-16T15:48:51Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-16T15:48:51Z [WARN][N3IWF][NGAP] No NAS signalling session found, retry... 2022-02-16T15:48:52Z [WARN][N3IWF][NGAP] No connection found for UE to send NAS message. This message will be cached in N3IWF

fasferraz commented 2 years ago

The signaling tunnel is created inside the namespace tcp_socket_signalling:

root@ubuntu:~# ip netns exec tcp_socket_signalling bash root@ubuntu:~# ifconfig tun2: flags=4305<UP,POINTOPOINT,RUNNING,NOARP,MULTICAST> mtu 1500 inet 10.0.0.251 netmask 255.255.255.255 destination 10.0.0.251 inet6 fe80::6470:e2e9:37f4:18b7 prefixlen 64 scopeid 0x20 unspec 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00 txqueuelen 500 (UNSPEC) RX packets 11 bytes 719 (719.0 B) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 18 bytes 977 (977.0 B) TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

root@ubuntu:~#

The same happens with tun3 if you create the user plane in a namespace (option -n (in the example -n TESTE)):

root@ubuntu:~# ip netns exec TESTE bash root@ubuntu:~# ifconfig tun3: flags=4305<UP,POINTOPOINT,RUNNING,NOARP,MULTICAST> mtu 1500 inet 60.60.0.1 netmask 255.255.255.255 destination 60.60.0.1 inet6 fe80::f362:b2dc:a7b7:54da prefixlen 64 scopeid 0x20 unspec 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00 txqueuelen 500 (UNSPEC) RX packets 0 bytes 0 (0.0 B) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 7 bytes 336 (336.0 B) TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0

root@ubuntu:~#

Can you do a tcpdump -i any -w trace.pcap in the free5gc VM? and also send me the application log output because i need the keys, so that i'm able to decode ike and ipsec in wireshark. Can you send it to my email please?