search

free5gc / smf

Apache License 2.0
19 stars 93 forks source link

SMF crashed and PDU session duplicated #47

Open minziran opened 2 years ago

minziran commented 2 years ago

Before SMF crashed, SMF assigned an IP 60.60.0.1 to UE imsi-208930000000004. Then, SMF crashed. After recovery, it assigned the same IP 60.60.0.1 to UE imsi-208930000000003.

`smf 2022-03-24T05:57:35Z [INFO][SMF][App] SMF version:
free5GC version: v3.0.6 build time: 2022-03-08T19:56:36Z commit hash: 46644f0a commit time: 2021-09-13T13:23:12Z go version: go1.14.4 linux/amd64 2022-03-24T05:57:35Z [INFO][SMF][Init] SMF Log level is set to [info] level 2022-03-24T05:57:35Z [INFO][LIB][NAS] set log level : info 2022-03-24T05:57:35Z [INFO][LIB][NAS] set report call : false 2022-03-24T05:57:35Z [INFO][LIB][NGAP] set log level : info 2022-03-24T05:57:35Z [INFO][LIB][NGAP] set report call : false 2022-03-24T05:57:35Z [INFO][LIB][Aper] set log level : info 2022-03-24T05:57:35Z [INFO][LIB][Aper] set report call : false 2022-03-24T05:57:35Z [INFO][LIB][Path] set log level : info 2022-03-24T05:57:35Z [INFO][LIB][Path] set report call : false 2022-03-24T05:57:35Z [INFO][LIB][OAPI] set log level : info 2022-03-24T05:57:35Z [INFO][LIB][OAPI] set report call : false 2022-03-24T05:57:35Z [INFO][LIB][PFCP] set log level : info 2022-03-24T05:57:35Z [INFO][LIB][PFCP] set report call : false 2022-03-24T05:57:35Z [INFO][SMF][CFG] SMF config version [1.0.2] 2022-03-24T05:57:35Z [INFO][SMF][CFG] UE-Routing config version [1.0.1] 2022-03-24T05:57:35Z [INFO][SMF][CTX] smfconfig Info: Version[1.0.2] Description[SMF initial local configuration] 2022-03-24T05:57:35Z [INFO][SMF][CTX] Endpoints: [upf0.free5gc.org] 2022-03-24T05:57:35Z [INFO][SMF][CTX] Endpoints: [upf1.free5gc.org] 2022-03-24T05:57:35Z [INFO][SMF][CTX] Endpoints: [upf2.free5gc.org] 2022-03-24T05:57:35Z [INFO][SMF][CTX] Endpoints: [upf3.free5gc.org] 2022-03-24T05:57:35Z [INFO][SMF][CTX] ue routing config Info: Version[1.0.1] Description[Routing information for UE] 2022-03-24T05:57:35Z [INFO][SMF][PduSess] In NewUEPreConfigPaths 2022-03-24T05:57:35Z [INFO][SMF][PduSess] In NewUEPreConfigPaths 2022-03-24T05:57:35Z [INFO][SMF][PduSess] In NewUEPreConfigPaths 2022-03-24T05:57:35Z [INFO][SMF][Init] Server started 2022-03-24T05:57:36Z [INFO][SMF][Init] SMF Registration to NRF {45e50e9b-2152-4a36-b1cb-0ab9da9417ff SMF REGISTERED 0 0xc00000c240 0xc00000c280 [] [] [smf.free5gc.org] [] [] [] 0 0 0 area1 0xc0000a6180 map[] false 0xc00000c0c0 false false []} 2022-03-24T05:57:36Z [INFO][SMF][PFCP] Listen on 10.100.200.8:8805 2022-03-24T05:57:36Z [INFO][SMF][App] Send PFCP Association Request to UPFupf1.free5gc.org 2022-03-24T05:57:36Z [INFO][SMF][App] Send PFCP Association Request to UPFupf2.free5gc.org 2022-03-24T05:57:36Z [INFO][SMF][App] Send PFCP Association Request to UPFupf3.free5gc.org 2022-03-24T05:57:36Z [INFO][SMF][App] Send PFCP Association Request to UPFupf0.free5gc.org 2022-03-24T05:57:36Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:57:36Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:57:36Z [INFO][LIB][PFCP] Remove Request Transaction [2] 2022-03-24T05:57:36Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.202] 2022-03-24T05:57:36Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:57:36Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.200] 2022-03-24T05:57:36Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.203] 2022-03-24T05:57:36Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:57:36Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.201] 2022-03-24T05:57:36Z [INFO][LIB][PFCP] Remove Request Transaction [3] 2022-03-24T05:57:36Z [INFO][LIB][PFCP] Remove Request Transaction [4] 2022-03-24T05:57:36Z [INFO][LIB][PFCP] Remove Request Transaction [1] 2022-03-24T05:57:36Z [INFO][SMF][PFCP] UPF(10.100.200.200)[internet] setup association 2022-03-24T05:57:36Z [INFO][SMF][PFCP] UPF(10.100.200.203)[internet3] setup association 2022-03-24T05:57:36Z [INFO][SMF][PFCP] UPF(10.100.200.202)[internet2] setup association 2022-03-24T05:57:36Z [INFO][SMF][PFCP] UPF(10.100.200.201)[internet0] setup association 2022-03-24T05:58:56Z [INFO][SMF][PduSess] Recieve Create SM Context Request 2022-03-24T05:58:56Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-03-24T05:58:56Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2022-03-24T05:58:56Z [INFO][SMF][CTX] Allocated UE IP address: 60.60.0.1 2022-03-24T05:58:56Z [INFO][SMF][CTX] Selected UPF: AnchorUPF0 2022-03-24T05:58:56Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2022-03-24T05:58:56Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc00050d720 0xc00050d760] 2022-03-24T05:58:56Z [INFO][SMF][GSM] Protocol Configuration Options 2022-03-24T05:58:56Z [INFO][SMF][GSM] &{[0xc00050d720 0xc00050d760]} 2022-03-24T05:58:56Z [INFO][SMF][GSM] Didn't Implement container type IPAddressAllocationViaNASSignallingUL 2022-03-24T05:58:56Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-208930000000004] PDUSessionID[1] 2022-03-24T05:58:56Z [INFO][SMF][PduSess] SUPI[imsi-208930000000004] has pre-config route 2022-03-24T05:58:56Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2022-03-24T05:58:56Z [INFO][SMF][GIN] | 201 | 10.100.200.102 | POST | /nsmf-pdusession/v1/sm-contexts | 2022-03-24T05:58:56Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse 2022-03-24T05:58:56Z [INFO][LIB][PFCP] Remove Request Transaction [5] &{200 Mbps 100 Mbps} 2022-03-24T05:58:56Z [INFO][SMF][PduSess] Recieve Update SM Context Request 2022-03-24T05:58:56Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-03-24T05:58:56Z [INFO][LIB][PFCP] Remove Request Transaction [6] 2022-03-24T05:58:56Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse 2022-03-24T05:58:56Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept 2022-03-24T05:58:56Z [INFO][SMF][PFCP] Add PSAAndULCL 2022-03-24T05:58:56Z [INFO][SMF][GIN] | 200 | 10.100.200.102 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:e4711b42-9594-4ff2-85f6-1970cf63602f/modify | panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0xb3433b]

goroutine 48 [running]: github.com/free5gc/smf/context.(*SMContext).AllocateLocalSEIDForDataPath(0xc0003ae000, 0x0) /go/src/free5gc/NFs/smf/context/sm_context.go:309 +0x8b github.com/free5gc/smf/producer.AddPDUSessionAnchorAndULCL(0xc0003ae000, 0x2, 0xc0004280a0, 0x10, 0x10) /go/src/free5gc/NFs/smf/producer/ulcl_procedure.go:23 +0x2c5 github.com/free5gc/smf/pfcp/handler.HandlePfcpSessionModificationResponse(0xc000536950) /go/src/free5gc/NFs/smf/pfcp/handler/handler.go:248 +0x6c4 github.com/free5gc/smf/pfcp.Dispatch(0xc000536950) /go/src/free5gc/NFs/smf/pfcp/dispatcher.go:45 +0x48a created by github.com/free5gc/smf/pfcp/udp.Run.func1 /go/src/free5gc/NFs/smf/pfcp/udp/udp.go:44 +0x1d1 smf 2022-03-24T05:58:57Z [INFO][SMF][App] SMF version:
free5GC version: v3.0.6 build time: 2022-03-08T19:56:36Z commit hash: 46644f0a commit time: 2021-09-13T13:23:12Z go version: go1.14.4 linux/amd64 2022-03-24T05:58:57Z [INFO][SMF][Init] SMF Log level is set to [info] level 2022-03-24T05:58:57Z [INFO][LIB][NAS] set log level : info 2022-03-24T05:58:57Z [INFO][LIB][NAS] set report call : false 2022-03-24T05:58:57Z [INFO][LIB][NGAP] set log level : info 2022-03-24T05:58:57Z [INFO][LIB][NGAP] set report call : false 2022-03-24T05:58:57Z [INFO][LIB][Aper] set log level : info 2022-03-24T05:58:57Z [INFO][LIB][Aper] set report call : false 2022-03-24T05:58:57Z [INFO][LIB][Path] set log level : info 2022-03-24T05:58:57Z [INFO][LIB][Path] set report call : false 2022-03-24T05:58:57Z [INFO][LIB][OAPI] set log level : info 2022-03-24T05:58:57Z [INFO][LIB][OAPI] set report call : false 2022-03-24T05:58:57Z [INFO][LIB][PFCP] set log level : info 2022-03-24T05:58:57Z [INFO][LIB][PFCP] set report call : false 2022-03-24T05:58:57Z [INFO][SMF][CFG] SMF config version [1.0.2] 2022-03-24T05:58:57Z [INFO][SMF][CFG] UE-Routing config version [1.0.1] 2022-03-24T05:58:57Z [INFO][SMF][CTX] smfconfig Info: Version[1.0.2] Description[SMF initial local configuration] 2022-03-24T05:58:57Z [INFO][SMF][CTX] Endpoints: [upf0.free5gc.org] 2022-03-24T05:58:57Z [INFO][SMF][CTX] Endpoints: [upf1.free5gc.org] 2022-03-24T05:58:57Z [INFO][SMF][CTX] Endpoints: [upf2.free5gc.org] 2022-03-24T05:58:57Z [INFO][SMF][CTX] Endpoints: [upf3.free5gc.org] 2022-03-24T05:58:57Z [INFO][SMF][CTX] ue routing config Info: Version[1.0.1] Description[Routing information for UE] 2022-03-24T05:58:57Z [INFO][SMF][PduSess] In NewUEPreConfigPaths 2022-03-24T05:58:57Z [INFO][SMF][PduSess] In NewUEPreConfigPaths 2022-03-24T05:58:57Z [INFO][SMF][PduSess] In NewUEPreConfigPaths 2022-03-24T05:58:57Z [INFO][SMF][Init] Server started 2022-03-24T05:58:57Z [INFO][SMF][Init] SMF Registration to NRF {82f6146f-220c-4414-ae0b-0d729c7226ab SMF REGISTERED 0 0xc00049a840 0xc00049a880 [] [] [smf.free5gc.org] [] [] [] 0 0 0 area1 0xc000122a80 map[] false 0xc00049a6c0 false false []} 2022-03-24T05:58:57Z [INFO][SMF][PFCP] Listen on 10.100.200.8:8805 2022-03-24T05:58:57Z [INFO][SMF][App] Send PFCP Association Request to UPFupf0.free5gc.org 2022-03-24T05:58:57Z [INFO][SMF][App] Send PFCP Association Request to UPFupf1.free5gc.org 2022-03-24T05:58:57Z [INFO][SMF][App] Send PFCP Association Request to UPFupf2.free5gc.org 2022-03-24T05:58:57Z [INFO][SMF][App] Send PFCP Association Request to UPFupf3.free5gc.org 2022-03-24T05:58:57Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:58:57Z [INFO][LIB][PFCP] Remove Request Transaction [1] 2022-03-24T05:58:57Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.200] 2022-03-24T05:58:57Z [INFO][SMF][PFCP] UPF(10.100.200.200)[internet] setup association 2022-03-24T05:58:57Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:58:57Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.203] 2022-03-24T05:58:57Z [INFO][LIB][PFCP] Remove Request Transaction [2] 2022-03-24T05:58:57Z [INFO][LIB][PFCP] Remove Request Transaction [4] 2022-03-24T05:58:57Z [INFO][LIB][PFCP] Remove Request Transaction [3] 2022-03-24T05:58:57Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:58:57Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-03-24T05:58:57Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.202] 2022-03-24T05:58:57Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.201] 2022-03-24T05:58:57Z [INFO][SMF][PFCP] UPF(10.100.200.202)[internet2] setup association 2022-03-24T05:58:57Z [INFO][SMF][PFCP] UPF(10.100.200.201)[internet0] setup association 2022-03-24T05:58:57Z [INFO][SMF][PFCP] UPF(10.100.200.203)[internet3] setup association 2022-03-24T06:00:49Z [INFO][SMF][PduSess] Recieve Create SM Context Request 2022-03-24T06:00:49Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-03-24T06:00:49Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2022-03-24T06:00:49Z [INFO][SMF][CTX] Allocated UE IP address: 60.60.0.1 2022-03-24T06:00:49Z [INFO][SMF][CTX] Selected UPF: AnchorUPF0 2022/03/24 06:00:49 http2: server connection error from 10.100.200.102:54962: connection error: PROTOCOL_ERROR 2022-03-24T06:00:49Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2022-03-24T06:00:49Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc00026d6a0 0xc00026d6e0] 2022-03-24T06:00:49Z [INFO][SMF][GSM] Protocol Configuration Options 2022-03-24T06:00:49Z [INFO][SMF][GSM] &{[0xc00026d6a0 0xc00026d6e0]} 2022-03-24T06:00:49Z [INFO][SMF][GSM] Didn't Implement container type IPAddressAllocationViaNASSignallingUL 2022-03-24T06:00:49Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-208930000000003] PDUSessionID[1] 2022-03-24T06:00:49Z [INFO][SMF][PduSess] SUPI[imsi-208930000000003] has pre-config route 2022-03-24T06:00:49Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2022-03-24T06:00:49Z [INFO][SMF][GIN] | 201 | 10.100.200.102 | POST | /nsmf-pdusession/v1/sm-contexts | 2022-03-24T06:00:49Z [INFO][LIB][PFCP] Remove Request Transaction [5] 2022-03-24T06:00:49Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse 2022-03-24T06:00:50Z [INFO][SMF][PduSess] Recieve Update SM Context Request 2022-03-24T06:00:50Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-03-24T06:00:50Z [WARN][SMF][PduSess] SMContext[imsi-208930000000003-01] should be Active, but actual ModificationPending 2022-03-24T06:00:50Z [INFO][SMF][CTX] [SMF] Cause_REL_DUE_TO_DUPLICATE_SESSION_ID 2022-03-24T06:00:50Z [INFO][SMF][PduSess] Send PFCP Deletion from HandlePDUSessionSMContextUpdate 2022-03-24T06:00:59Z [INFO][LIB][PFCP] Remove Request Transaction [6] 2022-03-24T06:07:13Z [INFO][SMF][GIN] | 404 | 10.100.200.5 | GET | /nsmf-oam/v1/ue-pdu-session-info/urn:uuid:e4711b42-9594-4ff2-85f6-1970cf63602f | 2022-03-24T06:07:17Z [INFO][SMF][GIN] | 404 | 10.100.200.5 | GET | /nsmf-oam/v1/ue-pdu-session-info/urn:uuid:e4711b42-9594-4ff2-85f6-1970cf63602f |`