########################################### UE sends PDU Session Establishment Request ########################################### [2021-07-22 10:31:17.048] [nas] [debug] Sending PDU Session Establishment Request 2021-07-22T10:31:17Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle Initial Context Setup Response 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] RanUeNgapID[2] AmfUeNgapID[2] 2021-07-22T10:31:17Z [TRAC][AMF][NGAP] Read 57 bytes 2021-07-22T10:31:17Z [TRAC][AMF][NGAP] Packet content: 00000000 00 2e 40 35 00 00 04 00 0a 00 02 00 02 00 55 00 |..@5..........U.| 00000010 02 00 02 00 26 00 0b 0a 7e 02 bb 22 12 93 01 7e |....&...~.."...~| 00000020 00 43 00 79 40 13 50 02 f8 39 00 00 00 01 00 02 |.C.y@.P..9......| 00000030 f8 39 00 00 01 e4 a3 c7 75 |.9......u| 2021-07-22T10:31:17Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle Uplink Nas Transport 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE NasPdu 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE UserLocationInformation 2021-07-22T10:31:17Z [INFO][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:2] Uplink NAS Transport (RAN UE NGAP ID: 2) 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] securityHeaderType is 2 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] securityHeader is [126 2 187 34 18 147] 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] sequenceNumber 1 2021-07-22T10:31:17Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Security header type: Integrity Protected And Ciphered 2021-07-22T10:31:17Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Calculate NAS MAC (algorithm: 2, ULCount: 0x1) 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] NAS integrity key0x: 389712a959c4f15a84586272c11383b3 2021-07-22T10:31:17Z [DEBU][NAS][Security] Use NIA2 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] cmac value: 0xbb221293 2021-07-22T10:31:17Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Decrypt NAS message (algorithm: 0, ULCount: 0x1) 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] NAS ciphering key: eb3cb79900d744ca2b45258039ff51d4 2021-07-22T10:31:17Z [DEBU][NAS][Security] Use NEA0 2021-07-22T10:31:17Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] GmmMessageEvent at GMM State[ContextSetup] 2021-07-22T10:31:17Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Handle Registration Complete 2021-07-22T10:31:17Z [DEBU][AMF][GMM] Exit event 2021-07-22T10:31:17Z [DEBU][AMF][GMM] ContextSetup Success 2021-07-22T10:31:17Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] EntryEvent at GMM State[Registered] 2021-07-22T10:31:17Z [TRAC][AMF][NGAP] Read 101 bytes 2021-07-22T10:31:17Z [TRAC][AMF][NGAP] Packet content: 00000000 00 2e 40 61 00 00 04 00 0a 00 02 00 02 00 55 00 |..@a..........U.| 00000010 02 00 02 00 26 00 37 36 7e 02 e0 0f 8c 69 02 7e |....&.76~....i.~| 00000020 00 67 01 00 15 2e 01 01 c1 ff ff 91 a1 28 01 00 |.g...........(..| 00000030 7b 00 07 80 00 0a 00 00 0d 00 12 01 81 22 04 01 |{............"..| 00000040 01 02 03 25 09 08 69 6e 74 65 72 6e 65 74 00 79 |...%..internet.y| 00000050 40 13 50 02 f8 39 00 00 00 01 00 02 f8 39 00 00 |@.P..9.......9..| 00000060 01 e4 a3 c7 75 |....u| 2021-07-22T10:31:17Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle Uplink Nas Transport 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE NasPdu 2021-07-22T10:31:17Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE UserLocationInformation 2021-07-22T10:31:17Z [INFO][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:2] Uplink NAS Transport (RAN UE NGAP ID: 2) 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] securityHeaderType is 2 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] securityHeader is [126 2 224 15 140 105] 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] sequenceNumber 2 2021-07-22T10:31:17Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Security header type: Integrity Protected And Ciphered 2021-07-22T10:31:17Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Calculate NAS MAC (algorithm: 2, ULCount: 0x2) 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] NAS integrity key0x: 389712a959c4f15a84586272c11383b3 2021-07-22T10:31:17Z [DEBU][NAS][Security] Use NIA2 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] cmac value: 0xe00f8c69 2021-07-22T10:31:17Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Decrypt NAS message (algorithm: 0, ULCount: 0x2) 2021-07-22T10:31:17Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] NAS ciphering key: eb3cb79900d744ca2b45258039ff51d4 2021-07-22T10:31:17Z [DEBU][NAS][Security] Use NEA0 2021-07-22T10:31:17Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] GmmMessageEvent at GMM State[Registered] 2021-07-22T10:31:17Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Handle UL NAS Transport 2021-07-22T10:31:17Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Transport 5GSM Message to SMF 2021-07-22T10:31:17Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Select SMF [snssai: {Sst:1 Sd:010203}, dnn: internet] 2021-07-22T10:31:17Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2021-07-22T10:31:17Z [TRAC][NRF][DSCV] Query filter: map[$and:[map[nfType:NSSF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]]]] 2021-07-22T10:31:17Z [INFO][NSSF][NsSelect] Handle NSSelectionGet 2021-07-22T10:31:17Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] Search SMF from NRF[http://free5gc-nrf:8000] 2021-07-22T10:31:17Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2021-07-22T10:31:17Z [TRAC][NRF][DSCV] temp target Plmn: {"mcc":"208","mnc":"93"} 2021-07-22T10:31:17Z [TRAC][NRF][DSCV] Query filter: map[$and:[map[nfType:SMF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]] map[nfServices:map[$elemMatch:map[nfServiceStatus:REGISTERED serviceName:map[$in:[nsmf-pdusession]]]]] map[$or:[map[plmnList:map[$elemMatch:map[mcc:208 mnc:93]]]]] map[$or:[map[sNssais:map[$elemMatch:map[sd:010203 sst:1]]] map[sNssais:map[$exists:false]]]] map[smfInfo.sNssaiSmfInfoList:map[$elemMatch:map[dnnSmfInfoList:map[$elemMatch:map[dnn:internet]]]]]]] 2021-07-22T10:31:17Z [INFO][SMF][PduSess] Recieve Create SM Context Request 2021-07-22T10:31:17Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2021-07-22T10:31:17Z [TRAC][SMF][CTX] SMContextState Change State: ActivePending 2021-07-22T10:31:17Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2021-07-22T10:31:17Z [TRAC][NRF][DSCV] Query filter: map[$and:[map[nfType:UDM] map[$or:[map[allowedNfTypes:SMF] map[allowedNfTypes:map[$exists:false]]]]]] 2021-07-22T10:31:17Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2021-07-22T10:31:17Z [INFO][UDM][SDM] Handle GetSmData 2021-07-22T10:31:17Z [INFO][UDM][SDM] getSmDataProcedure: SUPI[imsi-208930000007486] PLMNID[20893] DNN[internet] SNssai[{"sst":1,"sd":"010203"}] 2021-07-22T10:31:17Z [INFO][UDR][DRepo] Handle QuerySmData 2021-07-22T10:31:17Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2021-07-22T10:31:17Z [TRAC][NAS][Convert] In ProtocolConfigurationOptions UnMarshal 2021-07-22T10:31:17Z [TRAC][NAS][Convert] Reading ID: 10 2021-07-22T10:31:17Z [TRAC][NAS][Convert] Reading Length: 0 2021-07-22T10:31:17Z [TRAC][NAS][Convert] For loop ProtocolOrContainerList: [0xc0002e5ae0] 2021-07-22T10:31:17Z [TRAC][NAS][Convert] Reading ID: 13 2021-07-22T10:31:17Z [TRAC][NAS][Convert] Reading Length: 0 2021-07-22T10:31:17Z [TRAC][NAS][Convert] For loop ProtocolOrContainerList: [0xc0002e5ae0 0xc0002e5b20] 2021-07-22T10:31:17Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc0002e5ae0 0xc0002e5b20] 2021-07-22T10:31:17Z [INFO][SMF][GSM] Protocol Configuration Options 2021-07-22T10:31:17Z [INFO][SMF][GSM] &{[0xc0002e5ae0 0xc0002e5b20]} 2021-07-22T10:31:17Z [TRAC][SMF][GSM] Container ID: 10 2021-07-22T10:31:17Z [TRAC][SMF][GSM] Container Length: 0 2021-07-22T10:31:17Z [INFO][SMF][GSM] Didn't Implement container type IPAddressAllocationViaNASSignallingUL 2021-07-22T10:31:17Z [TRAC][SMF][GSM] Container ID: 13 2021-07-22T10:31:17Z [TRAC][SMF][GSM] Container Length: 0 2021-07-22T10:31:17Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-208930000007486] PDUSessionID[1] 2021-07-22T10:31:17Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2021-07-22T10:31:17Z [TRAC][NRF][DSCV] Query filter: map[$and:[map[nfType:PCF] map[$or:[map[allowedNfTypes:SMF] map[allowedNfTypes:map[$exists:false]]]]]] 2021-07-22T10:31:17Z [INFO][PCF][SMpolicy] Handle CreateSmPolicy 2021-07-22T10:31:17Z [TRAC][PCF][SMpolicy] Handle Create SM Policy Request 2021-07-22T10:31:17Z [TRAC][PCF][SMpolicy] SMPolicy PduSessionId[1] Create 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] In ApplySmPolicyFromDecision 2021-07-22T10:31:17Z [DEBU][SMF][PduSess] Install SessionRule[SessRuleId-1] 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] End of ApplySmPolicyFromDecision CheckUEHasPreConfig map[imsi-208930000005001:0xc00049d700 imsi-208930000005002:0xc00049d820 imsi-208930000005003:0xc00049d940 imsi-208930000005004:0xc00049da60 imsi-208930000005005:0xc00049db80 imsi-208930000005006:0xc00049dca0 imsi-208930000007481:0xc00049d5e0 imsi-208930000007482:0xc00049d4c0 imsi-208930000007483:0xc00049d3a0 imsi-208930000007484:0xc00049d280 imsi-208930000007485:0xc00049d160 imsi-208930000007486:0xc00049d040] 2021-07-22T10:31:17Z [INFO][SMF][PduSess] SUPI[imsi-208930000007486] has pre-config route 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] In AllocateLocalSEIDForDataPath 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] NodeIDtoIP: 192.168.159.56 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] NodeIDtoIP: 192.168.159.43 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] In ActivateTunnelAndPDR 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] DataPath Meta Information Activated: true IsDefault Path: true Has Braching Point: false Destination IP: 60.60.0.100 Destination Port: DataPath Routing Information 1th Node in the Path Current UPF IP: 192.168.159.56 Previous UPF IP: None Next UPF IP: 192.168.159.43 2th Node in the Path Current UPF IP: 192.168.159.43 Previous UPF IP: 192.168.159.56 Next UPF IP: None 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Current DP Node IP: 192.168.159.56 2021-07-22T10:31:17Z [TRAC][SMF][CTX] In ActivateUpLinkTunnel 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Current DP Node IP: 192.168.159.43 2021-07-22T10:31:17Z [TRAC][SMF][CTX] In ActivateUpLinkTunnel 2021-07-22T10:31:17Z [TRAC][SMF][CTX] Calculate 192.168.159.56:8805 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Current DP Node IP: 192.168.159.56 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Before DLPDR OuterHeaderCreation 2021-07-22T10:31:17Z [TRAC][SMF][CTX] Calculate 192.168.159.43:8805 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Current DP Node IP: 192.168.159.43 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Before DLPDR OuterHeaderCreation 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] In DLPDR OuterHeaderCreation 2021-07-22T10:31:17Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest 2021-07-22T10:31:17Z [TRAC][NRF][DSCV] Query filter: map[$and:[map[nfType:AMF] map[$or:[map[allowedNfTypes:SMF] map[allowedNfTypes:map[$exists:false]]]] map[nfInstanceId:e9f76058-fcbc-43cb-ba1a-258d2ca4a6e4]]] 2021-07-22T10:31:17Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Send NF Discovery Serving AMF successfully 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] [SMF] Send SendPfcpSessionEstablishmentRequest 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Send to addr 192.168.159.56:8805 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] New Transaction SEQ[10] DestAddr[192.168.159.56:8805] 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] In PutTransaction 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] End PutTransaction 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] [SMF] Send SendPfcpSessionEstablishmentRequest 2021-07-22T10:31:17Z [TRAC][SMF][PduSess] Send to addr 192.168.159.43:8805 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] New Transaction SEQ[11] DestAddr[192.168.159.43:8805] 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] In PutTransaction 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] End PutTransaction 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] Start Transaction [10] 2021/07/22 10:31:17 [Recovery] 2021/07/22 - 10:31:17 panic recovered: POST /nsmf-pdusession/v1/sm-contexts HTTP/2.0 Host: free5gc-smf:8000 Accept: application/json Accept-Encoding: gzip Content-Length: 790 Content-Type: multipart/related; boundary="d342e6c0dea4f9586915650205456977afd3a31b538c110b9eca39a99a5d" User-Agent: OpenAPI-Generator/1.0.0/go runtime error: invalid memory address or nil pointer dereference /usr/local/go/src/runtime/panic.go:212 (0x449339) /usr/local/go/src/runtime/signal_unix.go:695 (0x449188) /go/src/free5gc/NFs/smf/pfcp/message/build.go:253 (0xb3be98) /go/src/free5gc/NFs/smf/pfcp/message/send.go:129 (0xb3d9a2) /go/src/free5gc/NFs/smf/producer/datapath.go:92 (0xb586ea) /go/src/free5gc/NFs/smf/producer/pdu_session.go:212 (0xb59ab2) /go/src/free5gc/NFs/smf/pdusession/api_sm_contexts_collection.go:54 (0xb6b484) /go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 (0x996f5a) /go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/recovery.go:83 (0x9a932f) /go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 (0x996f5a) /go/pkg/mod/github.com/free5gc/logger_util@v1.0.0/logger_util.go:65 (0x9aaedd) /go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/context.go:161 (0x996f5a) /go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/gin.go:409 (0x9a0a05) /go/pkg/mod/github.com/gin-gonic/gin@v1.6.3/gin.go:367 (0x9a011c) /go/pkg/mod/golang.org/x/net@v0.0.0-20201209123823-ac852fbbde11/http2/server.go:2152 (0x9ce96a) /usr/local/go/src/runtime/asm_amd64.s:1373 (0x463030) 2021-07-22T10:31:17Z [INFO][SMF][GIN] | 500 | 192.168.159.60 | POST | /nsmf-pdusession/v1/sm-contexts | 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] Start Transaction [11] 2021-07-22T10:31:17Z [ERRO][AMF][GMM][AMF_UE_NGAP_ID:2][SUPI:imsi-208930000007486] CreateSmContextRequest Error: undefined response type 2021-07-22T10:31:17Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.56:8805, (remote get) 192.168.159.56:8805 2021-07-22T10:31:17Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.43:8805, (remote get) 192.168.159.43:8805 2021-07-22T10:31:17Z [TRAC][UPF][Util] UPF Establishment UPF SEID: 2 2021-07-22T10:31:17Z [TRAC][UPF][Util] [11] remote Create peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [TRAC][UPF][Util] [11] remote Receive peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [TRAC][UPF][Util] [11] remote UDP RX-50 peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create FAR 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR ID: 6 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR ID: 6 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get apply action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 100663296 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create FAR 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR ID: 8 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] Outer Header Creation Description: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] Outer Header Creation TEID: 6 2021-07-22T10:31:17Z [DEBU][UPF][Util] Outer Header Creation IPv4: 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR ID: 8 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[0], TEID[6], IP[192.168.159.56], Port[2152] 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get apply action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get description: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get peer ipv4: 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get port: 26632 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 134217728 2021-07-22T10:31:17Z [TRAC][UPF][Util] UPF Establishment UPF SEID: 2 2021-07-22T10:31:17Z [TRAC][UPF][Util] [10] remote Create peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [TRAC][UPF][Util] [10] remote Receive peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [TRAC][UPF][Util] [10] remote UDP RX-50 peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create FAR 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR ID: 10 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] Outer Header Creation Description: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] Outer Header Creation TEID: 3 2021-07-22T10:31:17Z [DEBU][UPF][Util] Outer Header Creation IPv4: 192.168.159.43 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR ID: 10 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[1], TEID[3], IP[192.168.159.43], Port[2152] 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get apply action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get description: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get peer ipv4: 192.168.159.43 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get port: 26632 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 167772160 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create FAR 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR ID: 12 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR ID: 12 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get apply action: 2 2021-07-22T10:31:17Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 201326592 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create PDR 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 9 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDI Source Interface: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] F-TEID TEID: 5 2021-07-22T10:31:17Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR Outer Header Removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR FAR ID: 10 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR QER ID: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR ID: 9 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 5, 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 10 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get farId: 167772160 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get outer header removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get teid: 83886080 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 2304 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create PDR 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 11 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDI Source Interface: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] F-TEID TEID: 6 2021-07-22T10:31:17Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR Outer Header Removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR FAR ID: 12 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR QER ID: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR ID: 11 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 6, 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 12 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get farId: 201326592 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get outer header removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get teid: 100663296 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 2816 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] In FindTransaction 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] End FindTransaction 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] Request Transaction [10]: receive valid response 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] In RemoveTransaction 2021-07-22T10:31:17Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse &{1 Kbps 1 Kbps} 2021-07-22T10:31:17Z [INFO][LIB][PFCP] Remove Request Transaction [10] 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] End RemoveTransaction 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create PDR 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 5 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDI Source Interface: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] F-TEID TEID: 3 2021-07-22T10:31:17Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.43 2021-07-22T10:31:17Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR Outer Header Removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR FAR ID: 6 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR QER ID: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR ID: 5 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 3, 192.168.159.43 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 6 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get farId: 100663296 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get outer header removal: 0 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get teid: 50331648 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.43 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 1280 2021-07-22T10:31:17Z [DEBU][UPF][Util] Handle Create PDR 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 7 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR ID: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDI Source Interface: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR FAR ID: 8 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR QER ID: 1 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR ID: 7 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 8 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get farId: 134217728 2021-07-22T10:31:17Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.2 2021-07-22T10:31:17Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 1792 2021-07-22T10:31:17Z [DEBU][UPF][Util] PFCP session establishment response built! 2021-07-22T10:31:17Z [TRAC][UPF][Util] [11] remote UDP TX-51 peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [DEBU][UPF][Util] PFCP session establishment response built! 2021-07-22T10:31:17Z [TRAC][UPF][Util] [10] remote UDP TX-51 peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [TRAC][UPF][Util] [10] remote Commit peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [INFO][UPF][Util] [PFCP] Session Establishment Response 2021-07-22T10:31:17Z [TRAC][UPF][Util] [11] remote Commit peer [192.168.159.45]:8805 2021-07-22T10:31:17Z [INFO][UPF][Util] [PFCP] Session Establishment Response 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] In FindTransaction 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] End FindTransaction 2021-07-22T10:31:17Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] Request Transaction [11]: receive valid response 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] In RemoveTransaction 2021-07-22T10:31:17Z [INFO][LIB][PFCP] Remove Request Transaction [11] 2021-07-22T10:31:17Z [TRAC][LIB][PFCP] End RemoveTransaction 2021-07-22T10:31:17Z [INFO][AMF][Producer] Handle N1N2 Message Transfer Request 2021-07-22T10:31:17Z [DEBU][AMF][Producer][SUPI:imsi-208930000007486] Receive N1 SM Message (PDU Session ID: 1) 2021-07-22T10:31:17Z [INFO][AMF][GIN] | 404 | 192.168.159.45 | POST | /namf-comm/v1/ue-contexts/imsi-208930000007486/n1-n2-messages | 2021-07-22T10:31:17Z [TRAC][SMF][CTX] SMContextState Change State: Active 2021-07-22T10:31:17Z [WARN][SMF][PFCP] Send N1N2Transfer failed 2021-07-22T10:31:19Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:20Z [TRAC][UPF][Util] [Timer Debug] PfcpXactTimeout index 2 and event 3 2021-07-22T10:31:20Z [TRAC][UPF][Util] [11] remote Holding Timeout for step 2 type 51 peer [192.168.159.45]:8805 2021-07-22T10:31:20Z [TRAC][UPF][Util] [11] remote Delete Transaction for step 2 type 51 peer [192.168.159.45]:8805 2021-07-22T10:31:20Z [TRAC][UPF][Util] [11] remote Delete peer [192.168.159.45]:8805 2021-07-22T10:31:20Z [DEBU][UPF][Util] Index Free successful, total capacity[64], available[64] 2021-07-22T10:31:20Z [TRAC][UPF][Util] [Timer Debug] PfcpXactTimeout index 4 and event 3 2021-07-22T10:31:20Z [TRAC][UPF][Util] [10] remote Holding Timeout for step 2 type 51 peer [192.168.159.45]:8805 2021-07-22T10:31:20Z [TRAC][UPF][Util] [10] remote Delete Transaction for step 2 type 51 peer [192.168.159.45]:8805 2021-07-22T10:31:20Z [TRAC][UPF][Util] [10] remote Delete peer [192.168.159.45]:8805 2021-07-22T10:31:20Z [DEBU][UPF][Util] Index Free successful, total capacity[64], available[64] 2021-07-22T10:31:21Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:23Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:25Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:27Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:29Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:31Z [DEBU][AMF][NGAP] SCTP read timeout 2021-07-22T10:31:33Z [DEBU][AMF][NGAP] SCTP read timeout ########################################### PDU fail (UE side) ########################################### [2021-07-22 10:31:33.928] [nas] [warning] Retransmitting PDU Session Establishment Request due to T3580 expiry