###########################################
UE sends PDU Session Establishment Request
###########################################

[2021-07-22 10:30:29.531] [nas] [debug] Sending PDU Session Establishment Request
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle Initial Context Setup Response
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] RanUeNgapID[1] AmfUeNgapID[1]
2021-07-22T10:30:29Z [TRAC][AMF][NGAP] Read 57 bytes
2021-07-22T10:30:29Z [TRAC][AMF][NGAP] Packet content:
00000000  00 2e 40 35 00 00 04 00  0a 00 02 00 01 00 55 00  |..@5..........U.|
00000010  02 00 01 00 26 00 0b 0a  7e 02 e2 a1 bb 18 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  45                       |.9......E|
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle Uplink Nas Transport
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE NasPdu
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE UserLocationInformation
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] securityHeaderType is  2
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] securityHeader is  [126 2 226 161 187 24]
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] sequenceNumber 1
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Security header type: Integrity Protected And Ciphered
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Calculate NAS MAC (algorithm: 2, ULCount: 0x1)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] NAS integrity key0x: aeb9805d5b6f43271fc13f4f127176b4
2021-07-22T10:30:29Z [DEBU][NAS][Security] Use NIA2
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] cmac value: 0xe2a1bb18
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Decrypt NAS message (algorithm: 0, ULCount: 0x1)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] NAS ciphering key: 4d4fa79c93e933e1f5b59d89a8863cd3
2021-07-22T10:30:29Z [DEBU][NAS][Security] Use NEA0
2021-07-22T10:30:29Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] GmmMessageEvent at GMM State[ContextSetup]
2021-07-22T10:30:29Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Handle Registration Complete
2021-07-22T10:30:29Z [DEBU][AMF][GMM] Exit event
2021-07-22T10:30:29Z [DEBU][AMF][GMM] ContextSetup Success
2021-07-22T10:30:29Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] EntryEvent at GMM State[Registered]
2021-07-22T10:30:29Z [TRAC][AMF][NGAP] Read 101 bytes
2021-07-22T10:30:29Z [TRAC][AMF][NGAP] Packet content:
00000000  00 2e 40 61 00 00 04 00  0a 00 02 00 01 00 55 00  |..@a..........U.|
00000010  02 00 01 00 26 00 37 36  7e 02 db 66 f4 1b 02 7e  |....&.76~..f...~|
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 45                                    |....E|
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle Uplink Nas Transport
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE NasPdu
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE UserLocationInformation
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] securityHeaderType is  2
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] securityHeader is  [126 2 219 102 244 27]
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] sequenceNumber 2
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Security header type: Integrity Protected And Ciphered
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Calculate NAS MAC (algorithm: 2, ULCount: 0x2)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] NAS integrity key0x: aeb9805d5b6f43271fc13f4f127176b4
2021-07-22T10:30:29Z [DEBU][NAS][Security] Use NIA2
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] cmac value: 0xdb66f41b
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Decrypt NAS message (algorithm: 0, ULCount: 0x2)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] NAS ciphering key: 4d4fa79c93e933e1f5b59d89a8863cd3
2021-07-22T10:30:29Z [DEBU][NAS][Security] Use NEA0
2021-07-22T10:30:29Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] GmmMessageEvent at GMM State[Registered]
2021-07-22T10:30:29Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Handle UL NAS Transport
2021-07-22T10:30:29Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Transport 5GSM Message to SMF
2021-07-22T10:30:29Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Select SMF [snssai: {Sst:1 Sd:010203}, dnn: internet]
2021-07-22T10:30:29Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2021-07-22T10:30:29Z [TRAC][NRF][DSCV] Query filter:  map[$and:[map[nfType:NSSF] map[$or:[map[allowedNfTypes:AMF] map[allowedNfTypes:map[$exists:false]]]]]]
2021-07-22T10:30:29Z [INFO][NSSF][NsSelect] Handle NSSelectionGet
2021-07-22T10:30:29Z [DEBU][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Search SMF from NRF[http://free5gc-nrf:8000]
2021-07-22T10:30:29Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2021-07-22T10:30:29Z [TRAC][NRF][DSCV] temp target Plmn: {"mcc":"208","mnc":"93"}
2021-07-22T10:30:29Z [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:30:29Z [INFO][SMF][PduSess] Recieve Create SM Context Request
2021-07-22T10:30:29Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate
2021-07-22T10:30:29Z [TRAC][SMF][CTX] SMContextState Change State:  ActivePending
2021-07-22T10:30:29Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2021-07-22T10:30:29Z [TRAC][NRF][DSCV] Query filter:  map[$and:[map[nfType:UDM] map[$or:[map[allowedNfTypes:SMF] map[allowedNfTypes:map[$exists:false]]]]]]
2021-07-22T10:30:29Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully
2021-07-22T10:30:29Z [INFO][UDM][SDM] Handle GetSmData
2021-07-22T10:30:29Z [INFO][UDM][SDM] getSmDataProcedure: SUPI[imsi-208930000007486] PLMNID[20893] DNN[internet] SNssai[{"sst":1,"sd":"010203"}]
2021-07-22T10:30:29Z [INFO][UDR][DRepo] Handle QuerySmData
2021-07-22T10:30:29Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest
2021-07-22T10:30:29Z [TRAC][NAS][Convert] In ProtocolConfigurationOptions UnMarshal
2021-07-22T10:30:29Z [TRAC][NAS][Convert] Reading ID:  10
2021-07-22T10:30:29Z [TRAC][NAS][Convert] Reading Length:  0
2021-07-22T10:30:29Z [TRAC][NAS][Convert] For loop ProtocolOrContainerList:  [0xc0004a4300]
2021-07-22T10:30:29Z [TRAC][NAS][Convert] Reading ID:  13
2021-07-22T10:30:29Z [TRAC][NAS][Convert] Reading Length:  0
2021-07-22T10:30:29Z [TRAC][NAS][Convert] For loop ProtocolOrContainerList:  [0xc0004a4300 0xc0004a4340]
2021-07-22T10:30:29Z [INFO][NAS][Convert] ProtocolOrContainerList:  [0xc0004a4300 0xc0004a4340]
2021-07-22T10:30:29Z [INFO][SMF][GSM] Protocol Configuration Options
2021-07-22T10:30:29Z [INFO][SMF][GSM] &{[0xc0004a4300 0xc0004a4340]}
2021-07-22T10:30:29Z [TRAC][SMF][GSM] Container ID:  10
2021-07-22T10:30:29Z [TRAC][SMF][GSM] Container Length:  0
2021-07-22T10:30:29Z [INFO][SMF][GSM] Didn't Implement container type IPAddressAllocationViaNASSignallingUL
2021-07-22T10:30:29Z [TRAC][SMF][GSM] Container ID:  13
2021-07-22T10:30:29Z [TRAC][SMF][GSM] Container Length:  0
2021-07-22T10:30:29Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-208930000007486] PDUSessionID[1]
2021-07-22T10:30:29Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2021-07-22T10:30:29Z [TRAC][NRF][DSCV] Query filter:  map[$and:[map[nfType:PCF] map[$or:[map[allowedNfTypes:SMF] map[allowedNfTypes:map[$exists:false]]]]]]
2021-07-22T10:30:29Z [INFO][PCF][SMpolicy] Handle CreateSmPolicy
2021-07-22T10:30:29Z [TRAC][PCF][SMpolicy] Handle Create SM Policy Request
2021-07-22T10:30:29Z [INFO][UDR][DRepo] Handle PolicyDataUesUeIdSmDataGet
2021-07-22T10:30:29Z [TRAC][PCF][SMpolicy] SMPolicy PduSessionId[1] Create
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In ApplySmPolicyFromDecision
2021-07-22T10:30:29Z [DEBU][SMF][PduSess] Install SessionRule[SessRuleId-1]
2021-07-22T10:30:29Z [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:30:29Z [INFO][SMF][PduSess] SUPI[imsi-208930000007486] has pre-config route
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In AllocateLocalSEIDForDataPath
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] NodeIDtoIP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] NodeIDtoIP:  192.168.159.43
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In ActivateTunnelAndPDR
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] DataPath Meta Information
Activated: false
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:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][CTX] In ActivateUpLinkTunnel
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.43
2021-07-22T10:30:29Z [TRAC][SMF][CTX] In ActivateUpLinkTunnel
2021-07-22T10:30:29Z [TRAC][SMF][CTX] Calculate  192.168.159.56:8805
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Before DLPDR OuterHeaderCreation
2021-07-22T10:30:29Z [TRAC][SMF][CTX] Calculate  192.168.159.43:8805
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.43
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Before DLPDR OuterHeaderCreation
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In DLPDR OuterHeaderCreation
2021-07-22T10:30:29Z [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2021-07-22T10:30:29Z [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:30:29Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Send NF Discovery Serving AMF successfully
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] [SMF] Send SendPfcpSessionEstablishmentRequest
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Send to addr  192.168.159.56:8805
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] New Transaction SEQ[4] DestAddr[192.168.159.56:8805]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End PutTransaction
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] [SMF] Send SendPfcpSessionEstablishmentRequest
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Send to addr  192.168.159.43:8805
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Start Transaction [4]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] New Transaction SEQ[5] DestAddr[192.168.159.43:8805]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End PutTransaction
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.56:8805, (remote get) 192.168.159.56:8805
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Start Transaction [5]
2021-07-22T10:30:29Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] create smContext[pduSessionID: 1] Success
2021-07-22T10:30:29Z [TRAC][UPF][Util] UPF Establishment UPF SEID: 1
2021-07-22T10:30:29Z [TRAC][UPF][Util] [4] remote Create  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [4] remote Receive peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [4] remote UDP RX-50 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation Description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation IPv4: 192.168.159.43
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.43:8805, (remote get) 192.168.159.43:8805
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[1], TEID[1], IP[192.168.159.43], Port[2152]
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get peer ipv4: 192.168.159.43
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get port: 26632
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create QER
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER Gate Status: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER MBR UL: 1, DL: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER QoS Flow Identifier: 9
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 1, 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 16777216
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 256
2021-07-22T10:30:29Z [TRAC][UPF][Util] UPF Establishment UPF SEID: 1
2021-07-22T10:30:29Z [TRAC][UPF][Util] [5] remote Create  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [5] remote Receive peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [5] remote UDP RX-50 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 2, 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 768
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP session establishment response built!
2021-07-22T10:30:29Z [TRAC][UPF][Util] [4] remote UDP TX-51 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [4] remote Commit  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Session Establishment Response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Request Transaction [4]: receive valid response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In RemoveTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse
&{1 Kbps 1 Kbps}
2021-07-22T10:30:29Z [INFO][LIB][PFCP] Remove Request Transaction [4]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End RemoveTransaction
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation Description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation TEID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[0], TEID[2], IP[192.168.159.56], Port[2152]
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get peer ipv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get port: 26632
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create QER
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER Gate Status: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER MBR UL: 1, DL: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER QoS Flow Identifier: 9
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.43
2021-07-22T10:30:29Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 1, 192.168.159.43
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 16777216
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.43
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 256
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 768
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP session establishment response built!
2021-07-22T10:30:29Z [TRAC][UPF][Util] [5] remote UDP TX-51 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [5] remote Commit  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End FindTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Request Transaction [5]: receive valid response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In RemoveTransaction
2021-07-22T10:30:29Z [INFO][LIB][PFCP] Remove Request Transaction [5]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End RemoveTransaction
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Session Establishment Response
2021-07-22T10:30:29Z [INFO][AMF][Producer] Handle N1N2 Message Transfer Request
2021-07-22T10:30:29Z [DEBU][AMF][Producer][SUPI:imsi-208930000007486] Receive N1 SM Message (PDU Session ID: 1)
2021-07-22T10:30:29Z [DEBU][AMF][Producer][SUPI:imsi-208930000007486] Receive N2 SM Message (PDU Session ID: 1)
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Security header type: Integrity Protected And Ciphered
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] plain payload:
00000000  7e 00 68 01 00 3a 2e 01  01 c2 11 00 09 01 00 06  |~.h..:..........|
00000010  31 31 01 01 ff 09 06 01  00 01 01 00 01 59 32 29  |11...........Y2)|
00000020  05 01 3c 3c 00 01 22 04  01 01 02 03 79 00 06 09  |..<<..".....y...|
00000030  20 41 01 01 09 25 09 08  69 6e 74 65 72 6e 65 74  | A...%..internet|
00000040  12 01                                             |..|
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Encrypt NAS message (algorithm: 0, DLCount: 0x2)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] NAS ciphering key: 4d4fa79c93e933e1f5b59d89a8863cd3
2021-07-22T10:30:29Z [DEBU][NAS][Security] Use NEA0
2021-07-22T10:30:29Z [DEBU][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] Calculate NAS MAC (algorithm: 2, DLCount: 0x2)
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] NAS integrity key: aeb9805d5b6f43271fc13f4f127176b4
2021-07-22T10:30:29Z [DEBU][NAS][Security] Use NIA2
2021-07-22T10:30:29Z [TRAC][AMF][NAS][AMF_UE_NGAP_ID:1][SUPI:imsi-208930000007486] MAC: 0x2aba9f98
2021-07-22T10:30:29Z [DEBU][AMF][Producer][SUPI:imsi-208930000007486] AMF Transfer NGAP PDU Session Resource Setup Request from SMF
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:1] Send PDU Session Resource Setup Request
2021-07-22T10:30:29Z [DEBU][AMF][NGAP][10.50.231.107:35440] Send NGAP message To Ran
2021-07-22T10:30:29Z [DEBU][AMF][NGAP][10.50.231.107:35440] Write 154 bytes
2021-07-22T10:30:29Z [TRAC][SMF][CTX] SMContextState Change State:  Active
[2021-07-22 10:30:29.832] [ngap] [info] PDU session resource(s) setup for UE[1] count[1]
2021-07-22T10:30:29Z [TRAC][AMF][NGAP] Read 40 bytes
2021-07-22T10:30:29Z [TRAC][AMF][NGAP] Packet content:
00000000  20 1d 00 24 00 00 03 00  0a 40 02 00 01 00 55 40  | ..$.....@....U@|
00000010  02 00 01 00 4b 40 11 00  00 01 0d 00 03 e0 0a 32  |....K@.........2|
00000020  e7 65 00 00 00 01 00 09                           |.e......|
[2021-07-22 10:30:29.828] [nas] [debug] PDU Session Establishment Accept received
[2021-07-22 10:30:29.828] [nas] [warning] SM cause received in PduSessionEstablishmentAccept [PDU_SESSION_TYPE_IPV4_ONLY_ALLOWED]
[2021-07-22 10:30:29.828] [nas] [info] PDU Session establishment is successful PSI[1]
2021-07-22T10:30:29Z [INFO][AMF][NGAP][10.50.231.107:35440] Handle PDU Session Resource Setup Response
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE AmfUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE RanUeNgapID
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440] Decode IE PDUSessionResourceSetupListSURes
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:1] AmfUeNgapID[1] RanUeNgapID[1]
2021-07-22T10:30:29Z [TRAC][AMF][NGAP][10.50.231.107:35440][AMF_UE_NGAP_ID:1] Send PDUSessionResourceSetupResponseTransfer to SMF
2021-07-22T10:30:29Z [INFO][SMF][PduSess] Recieve Update SM Context Request
2021-07-22T10:30:29Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] [SMF] Binary Data N1 SmMessage is nil!
2021-07-22T10:30:29Z [TRAC][SMF][CTX] SMContextState Change State:  ModificationPending
2021-07-22T10:30:29Z [TRAC][SMF][CTX] SMContextState Change State:  PFCPModification
2021-07-22T10:30:29Z [TRAC][SMF][CTX] In case PFCPModification
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] New Transaction SEQ[6] DestAddr[192.168.159.56:8805]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Start Transaction [6]
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.56:8805, (remote get) 192.168.159.56:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [6] remote Create  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [6] remote Receive peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [6] remote UDP RX-52 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Handle PFCP session modification request
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Update FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation Description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation IPv4: 10.50.231.101
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[0], TEID[1], IP[10.50.231.101], Port[2152]
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get peer ipv4: 10.50.231.101
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get port: 26632
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR modify to kernel, dev: upfgtp, far id: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Update PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 2, 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR modify to kernel, dev: upfgtp, pdr id: 768
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP session modification response built!
2021-07-22T10:30:29Z [TRAC][UPF][Util] [6] remote UDP TX-53 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [6] remote Commit  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Session Modification Response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Request Transaction [6]: receive valid response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In RemoveTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse
2021-07-22T10:30:29Z [INFO][LIB][PFCP] Remove Request Transaction [6]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End RemoveTransaction
2021-07-22T10:30:29Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Delete pending pfcp response: UPF IP [192.168.159.56]
2021-07-22T10:30:29Z [INFO][SMF][PFCP] Add PSAAndULCL
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In AllocateLocalSEIDForDataPath
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] NodeIDtoIP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] NodeIDtoIP:  192.168.159.48
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In AllocateLocalSEIDForDataPath
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] NodeIDtoIP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] NodeIDtoIP:  192.168.159.48
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In ActivateTunnelAndPDR
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] DataPath Meta Information
Activated: false
IsDefault Path: false
Has Braching Point: false
Destination IP: 60.60.0.101
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.48
2th Node in the Path
Current UPF IP: 192.168.159.48
Previous UPF IP: 192.168.159.56
Next UPF IP: None
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][CTX] In ActivateUpLinkTunnel
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.48
2021-07-22T10:30:29Z [TRAC][SMF][CTX] In ActivateUpLinkTunnel
2021-07-22T10:30:29Z [TRAC][SMF][CTX] Calculate  192.168.159.56:8805
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.56
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Before DLPDR OuterHeaderCreation
2021-07-22T10:30:29Z [TRAC][SMF][CTX] Calculate  192.168.159.48:8805
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Current DP Node IP:  192.168.159.48
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Before DLPDR OuterHeaderCreation
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In DLPDR OuterHeaderCreation
2021-07-22T10:30:29Z [INFO][SMF][PduSess] In EstablishPSA2
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Send to upf addr:  192.168.159.48:8805
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] [SMF] Send SendPfcpSessionEstablishmentRequest
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] Send to addr  192.168.159.48:8805
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] New Transaction SEQ[7] DestAddr[192.168.159.48:8805]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End PutTransaction
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] End of EstablishPSA2
2021-07-22T10:30:29Z [INFO][SMF][PFCP] PFCP Session Modification Success[1]
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PFCP Session Context
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc0001034c0 [] 0xc000103500 <nil> } 0xc0004ec118 0xc000400960 <nil> [0xc000400b70] 1}
PDR ID:  3
PDR: &{3 255 {{1} 0xc0001035c0 [] <nil> <nil> } 0xc0004ec128 0xc0004009c0 <nil> [0xc000400b70] 1}
PDR ID:  5
PDR: &{5 255 {{0} 0xc0001892c0 [] 0xc000189300 <nil> } 0xc000418858 0xc00041b0b0 <nil> [0xc000400b70] 0}
PDR ID:  7
PDR: &{7 255 {{1} 0xc0001893c0 [] <nil> <nil> } 0xc000418868 0xc00041b0e0 <nil> [0xc000400b70] 0}
Node ID:  192.168.159.56
LocalSEID:  1
RemoteSEID:  1
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc000103600 [] 0xc000103640 <nil> } 0xc0004ec2b8 0xc000400ae0 <nil> [0xc000400c90] 1}
PDR ID:  3
PDR: &{3 255 {{1} <nil> [105 110 116 101 114 110 101 116] 0xc000103780 <nil> } <nil> 0xc000400b40 <nil> [0xc000400c90] 1}
Node ID:  192.168.159.43
LocalSEID:  2
RemoteSEID:  1
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc000189480 [] 0xc0001894c0 <nil> } 0xc0004188f8 0xc00041b1a0 <nil> [0xc00041b2c0] 1}
PDR ID:  3
PDR: &{3 255 {{1} <nil> [105 110 116 101 114 110 101 116] 0xc000189600 <nil> } <nil> 0xc00041b200 <nil> [0xc00041b2c0] 0}
Node ID:  192.168.159.48
LocalSEID:  3
RemoteSEID:  0
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Start Transaction [7]
2021-07-22T10:30:29Z [TRAC][SMF][CTX] In case SessionUpdateSuccess
2021-07-22T10:30:29Z [TRAC][SMF][CTX] SMContextState Change State:  Active
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.48:8805, (remote get) 192.168.159.48:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] UPF Establishment UPF SEID: 1
2021-07-22T10:30:29Z [TRAC][UPF][Util] [7] remote Create  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [7] remote Receive peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [7] remote UDP RX-50 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create QER
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER Gate Status: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER MBR UL: 1, DL: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] QER QoS Flow Identifier: 9
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.48
2021-07-22T10:30:29Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 1, 192.168.159.48
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 33554432
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 16777216
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.48
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 256
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Request Transaction [7]: receive valid response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In RemoveTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse
2021-07-22T10:30:29Z [INFO][SMF][PFCP] Keep Adding PSAndULCL
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In UpdatePSA2DownLink
2021-07-22T10:30:29Z [INFO][SMF][PduSess] In EstablishULCL
2021-07-22T10:30:29Z [INFO][LIB][PFCP] Remove Request Transaction [7]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End RemoveTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] New Transaction SEQ[8] DestAddr[192.168.159.56:8805]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End PutTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] [SMF] Establish ULCL msg has been send
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Start Transaction [8]
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP session establishment response built!
2021-07-22T10:30:29Z [TRAC][UPF][Util] [7] remote UDP TX-51 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [7] remote Commit  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Session Establishment Response
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.56:8805, (remote get) 192.168.159.56:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [8] remote Create  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [8] remote Receive peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [8] remote UDP RX-52 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Handle PFCP session modification request
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 6
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation Description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation IPv4: 192.168.159.48
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 6
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[1], TEID[1], IP[192.168.159.48], Port[2152]
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get peer ipv4: 192.168.159.48
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get port: 26632
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 100663296
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 8
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation Description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation IPv4: 10.50.231.101
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 8
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[0], TEID[1], IP[10.50.231.101], Port[2152]
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get peer ipv4: 10.50.231.101
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get port: 26632
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 134217728
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 5
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 30
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] SDF Filter Flow Description: permit out ip from 60.60.0.1 to 60.60.0.101
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 6
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 5
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 30
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 1, 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set SDF Filter Flow Description: permit out ip from 60.60.0.1 to 60.60.0.101
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 6
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 503316480
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 100663296
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 16777216
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 1280
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 7
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID TEID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] F-TEID IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 8
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 7
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI F-TEID: 4, 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Outer Header Removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 8
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 134217728
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get outer header removal: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get teid: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get gtpu ip: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 1792
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP session modification response built!
2021-07-22T10:30:29Z [TRAC][UPF][Util] [8] remote UDP TX-53 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [8] remote Commit  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Session Modification Response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End FindTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse
2021-07-22T10:30:29Z [INFO][SMF][PFCP] Keep Adding PSAAndULCL
2021-07-22T10:30:29Z [TRAC][SMF][PduSess] In UpdatePSA2DownLink
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] New Transaction SEQ[9] DestAddr[192.168.159.48:8805]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In PutTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End PutTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] [SMF] Update PSA2 downlink msg has been send
2021-07-22T10:30:29Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept
2021-07-22T10:30:29Z [INFO][SMF][PFCP] PFCP Session Modification Success[1]
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PFCP Session Context
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Request Transaction [8]: receive valid response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In RemoveTransaction
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  3
PDR: &{3 255 {{1} <nil> [105 110 116 101 114 110 101 116] 0xc000103780 <nil> } <nil> 0xc000400b40 <nil> [0xc000400c90] 1}
PDR ID:  1
PDR: &{1 255 {{0} 0xc000103600 [] 0xc000103640 <nil> } 0xc0004ec2b8 0xc000400ae0 <nil> [0xc000400c90] 1}
Node ID:  192.168.159.43
LocalSEID:  2
RemoteSEID:  1
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc000189480 [] 0xc0001894c0 <nil> } 0xc0004188f8 0xc00041b1a0 <nil> [0xc00041b2c0] 1}
PDR ID:  3
PDR: &{3 255 {{1} <nil> [105 110 116 101 114 110 101 116] 0xc000189600 <nil> } <nil> 0xc00041b200 <nil> [0xc00041b2c0] 1}
Node ID:  192.168.159.48
LocalSEID:  3
RemoteSEID:  1
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc0001034c0 [] 0xc000103500 <nil> } 0xc0004ec118 0xc000400960 <nil> [0xc000400b70] 1}
PDR ID:  3
PDR: &{3 255 {{1} 0xc0001035c0 [] <nil> <nil> } 0xc0004ec128 0xc0004009c0 <nil> [0xc000400b70] 1}
PDR ID:  5
PDR: &{5 30 {{0} 0xc0001892c0 [] 0xc000189300 0xc00025a2a0 } 0xc000418858 0xc00041b0b0 <nil> [0xc000400b70] 1}
PDR ID:  7
PDR: &{7 255 {{1} 0xc0001893c0 [] <nil> <nil> } 0xc000418868 0xc00041b0e0 <nil> [0xc000400b70] 1}
Node ID:  192.168.159.56
LocalSEID:  1
RemoteSEID:  1
2021-07-22T10:30:29Z [INFO][LIB][PFCP] Remove Request Transaction [8]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End RemoveTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Start Transaction [9]
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP Receive packet: (local bind) 192.168.159.48:8805, (remote get) 192.168.159.48:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [9] remote Create  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [9] remote Receive peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [9] remote UDP RX-52 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Handle PFCP session modification request
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create FAR
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Destination Interface: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Forwarding Parameters Network Instance: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation Description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation TEID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] Outer Header Creation IPv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get FAR Apply Action: 0
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get Outer Header Creation: Desp[0], TEID[4], IP[192.168.159.56], Port[2152]
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get apply action: 2
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get description: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get peer ipv4: 192.168.159.56
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get port: 26632
2021-07-22T10:30:29Z [DEBU][UPF][Util] FAR add to kernel, dev: upfgtp, far id: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] Handle Create PDR
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR ID: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDI Source Interface: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] UE IP Address IPv4: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR QER ID: 1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR ID: 3
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR Precedence: 255
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDI UE IP Address: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g set PDR FAR ID: 4
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get precendence: 4278190080
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get farId: 67108864
2021-07-22T10:30:29Z [DEBU][UPF][Util] gtp5g get ue ip: 60.60.0.1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PDR add to kernel, dev: upfgtp, pdr id: 768
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End FindTransaction
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] Request Transaction [9]: receive valid response
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] In RemoveTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse
2021-07-22T10:30:29Z [INFO][SMF][PFCP] Keep Adding PSAAndULCL
2021-07-22T10:30:29Z [INFO][SMF][CTX] [SMF] Add PSA success
2021-07-22T10:30:29Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept
2021-07-22T10:30:29Z [INFO][LIB][PFCP] Remove Request Transaction [9]
2021-07-22T10:30:29Z [TRAC][LIB][PFCP] End RemoveTransaction
2021-07-22T10:30:29Z [INFO][SMF][PFCP] PFCP Session Modification Success[3]
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PFCP Session Context
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  5
PDR: &{5 30 {{0} 0xc0001892c0 [] 0xc000189300 0xc00025a2a0 } 0xc000418858 0xc00041b0b0 <nil> [0xc000400b70] 1}
PDR ID:  7
PDR: &{7 255 {{1} 0xc0001893c0 [] <nil> <nil> } 0xc000418868 0xc00041b0e0 <nil> [0xc000400b70] 1}
PDR ID:  1
PDR: &{1 255 {{0} 0xc0001034c0 [] 0xc000103500 <nil> } 0xc0004ec118 0xc000400960 <nil> [0xc000400b70] 1}
PDR ID:  3
PDR: &{3 255 {{1} 0xc0001035c0 [] <nil> <nil> } 0xc0004ec128 0xc0004009c0 <nil> [0xc000400b70] 1}
Node ID:  192.168.159.56
LocalSEID:  1
RemoteSEID:  1
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc000103600 [] 0xc000103640 <nil> } 0xc0004ec2b8 0xc000400ae0 <nil> [0xc000400c90] 1}
PDR ID:  3
PDR: &{3 255 {{1} <nil> [105 110 116 101 114 110 101 116] 0xc000103780 <nil> } <nil> 0xc000400b40 <nil> [0xc000400c90] 1}
Node ID:  192.168.159.43
LocalSEID:  2
RemoteSEID:  1
2021-07-22T10:30:29Z [TRAC][SMF][CTX] PDR ID:  1
PDR: &{1 255 {{0} 0xc000189480 [] 0xc0001894c0 <nil> } 0xc0004188f8 0xc00041b1a0 <nil> [0xc00041b2c0] 1}
PDR ID:  3
PDR: &{3 255 {{1} <nil> [105 110 116 101 114 110 101 116] 0xc000189600 <nil> } <nil> 0xc00041b200 <nil> [0xc00041b2c0] 1}
Node ID:  192.168.159.48
LocalSEID:  3
RemoteSEID:  1
2021-07-22T10:30:29Z [DEBU][UPF][Util] PFCP session modification response built!
2021-07-22T10:30:29Z [TRAC][UPF][Util] [9] remote UDP TX-53 peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [TRAC][UPF][Util] [9] remote Commit  peer [192.168.159.45]:8805
2021-07-22T10:30:29Z [INFO][UPF][Util] [PFCP] Session Modification Response

###########################################
UE got an IP
###########################################

[2021-07-22 10:30:29.853] [app] [info] Connection setup for PDU session[1] is successful, TUN interface[uesimtun0, 60.60.0.1] is up.