smContext is not released in TestPDUSessionReleaseRequest

[ShouheiNishi]

We run ./test.sh -o TestPDUSessionReleaseRequest . The IP release log is not seen.
So, it seems that previously, the smContext was released when the PDU Session Release Complete GMM message was received, but the latest version no longer releases the smContext.
We think this issue was introduced by the 995e883.

[ShouheiNishi]

I misunderstood, IP address is released. However, the smContext is not released.

We apply this patch to check the call of the function RemoveSMContext.

diff --git a/context/sm_context.go b/context/sm_context.go
index 6df2645..85de75b 100644
--- a/context/sm_context.go
+++ b/context/sm_context.go
@@ -198,6 +198,9 @@ func RemoveSMContext(ref string) {
                return
        }

+       logger.PduSessLog.Infof("RemoveSMContext: UE[%s] PDUSessionID[%d] Release IP[%s]",
+               smContext.Supi, smContext.PDUSessionID)
+
        if smContext.SelectedUPF != nil {
                logger.PduSessLog.Infof("UE[%s] PDUSessionID[%d] Release IP[%s]",
                        smContext.Supi, smContext.PDUSessionID, smContext.PDUAddress.String())

Try ./test.sh -o TestPDUSessionReleaseRequest. We can not see RemoveSMConext call.

nishi@GTP-U:~/free5gc-deb/free5gc$ ./test.sh -o TestPDUSessionReleaseRequest
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] UPF log: /home/nishi/free5gc-deb/free5gc/NFs/upf/build/log/upf.log
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] Config: /home/nishi/free5gc-deb/free5gc/NFs/upf/build/config/upfcfg.test.yaml
tcpdump: listening on any, link-type LINUX_SLL (Linux cooked v1), capture size 262144 bytes
tcpdump: listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] UPF config version [1.0.0]
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] Set log level: info
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] DNN routes added, main routing table:
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] DstIp               Gateway        Iface     Priority RtProto   Type
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] 60.60.0.0 /24       0.0.0.0        upfgtp    0        static    unicast
2022-03-23T15:26:24+09:00 [INFO][UPF][Util] 10.200.200.0 /24    0.0.0.0        veth1     0        kernel    unicast
2022-03-23T15:26:31+09:00 [INFO][NRF][Init] NRF Log level is set to [info] level
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][MonDB] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][MonDB] set report call : false
2022-03-23T15:26:31+09:00 [INFO][NRF][CFG] config version [1.0.0]
2022-03-23T15:26:31+09:00 [INFO][NRF][Init] Server started
2022-03-23T15:26:31+09:00 [INFO][NRF][Init] nrfconfig Info: Version[1.0.0] Description[NRF initial local configuration]
2022-03-23T15:26:31+09:00 [INFO][NRF][Init] Binding addr: [127.0.0.10:8000]
2022-03-23T15:26:31+09:00 [INFO][AMF][Init] AMF Log level is set to [info] level
2022-03-23T15:26:31+09:00 [INFO][LIB][NAS] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][NAS] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][NGAP] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][NGAP] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][FSM] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][FSM] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][Aper] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Aper] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:31+09:00 [INFO][AMF][CFG] config version [1.0.2]
2022-03-23T15:26:31+09:00 [INFO][AMF][Init] Server started
2022-03-23T15:26:31+09:00 [INFO][AMF][Util] amfconfig Info: Version[1.0.2] Description[AMF initial local configuration]
2022-03-23T15:26:31+09:00 [INFO][AMF][NGAP] Listen on 127.0.0.1:38412
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/2c395533-76ba-4a49-bf23-a3c5654d8099
2022-03-23T15:26:31+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/2c395533-76ba-4a49-bf23-a3c5654d8099 |
2022-03-23T15:26:31+09:00 [INFO][SMF][Init] SMF Log level is set to [info] level
2022-03-23T15:26:31+09:00 [INFO][LIB][NAS] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][NAS] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][NGAP] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][NGAP] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][Aper] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Aper] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][PFCP] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][PFCP] set report call : false
2022-03-23T15:26:31+09:00 [INFO][SMF][CFG] SMF config version [1.0.2]
2022-03-23T15:26:31+09:00 [INFO][SMF][CFG] UE-Routing config version [1.0.1]
2022-03-23T15:26:31+09:00 [INFO][SMF][CTX] smfconfig Info: Version[1.0.2] Description[SMF initial local configuration]
2022-03-23T15:26:31+09:00 [INFO][SMF][CTX] Endpoints: [10.200.200.102]
2022-03-23T15:26:31+09:00 [INFO][SMF][Init] Server started
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/bd3eabc2-95b2-425a-aca5-3e14a36bf24f
2022-03-23T15:26:31+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/bd3eabc2-95b2-425a-aca5-3e14a36bf24f |
2022-03-23T15:26:31+09:00 [INFO][SMF][Init] SMF Registration to NRF {bd3eabc2-95b2-425a-aca5-3e14a36bf24f SMF REGISTERED 0 0xc0000a1d80 0xc0000a1f20 [] []   [127.0.0.2] [] <nil> [] [] <nil> 0 0 0 area1 <nil> <nil> <nil> <nil> 0xc0000a5280 <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc0000a07a0 false false []}
2022-03-23T15:26:31+09:00 [INFO][SMF][PFCP] Listen on 10.200.200.1:8805
2022-03-23T15:26:31+09:00 [INFO][SMF][App] Send PFCP Association Request to UPF[10.200.200.101]
2022-03-23T15:26:31+09:00 [INFO][UPF][Util] [PFCP] Handle PFCP association setup request
2022-03-23T15:26:31+09:00 [INFO][UPF][Util] [PFCP] Association Setup Response
2022-03-23T15:26:31+09:00 [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse
2022-03-23T15:26:31+09:00 [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.200.200.101]
2022-03-23T15:26:31+09:00 [INFO][LIB][PFCP] Remove Request Transaction [1]
2022-03-23T15:26:31+09:00 [INFO][SMF][PFCP] UPF(10.200.200.101)[internet] setup association
2022-03-23T15:26:31+09:00 [INFO][UDR][Init] UDR Log level is set to [info] level
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][MonDB] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][MonDB] set report call : false
2022-03-23T15:26:31+09:00 [INFO][UDR][CFG] config version [1.0.0]
2022-03-23T15:26:31+09:00 [INFO][UDR][Init] UDR Config Info: Version[1.0.0] Description[UDR initial local configuration]
2022-03-23T15:26:31+09:00 [INFO][UDR][Init] Server started
2022-03-23T15:26:31+09:00 [INFO][UDR][Util] udrconfig Info: Version[1.0.0] Description[UDR initial local configuration]
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/e4eca06b-b5f7-4cf9-a441-06f375e00c7d
2022-03-23T15:26:31+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/e4eca06b-b5f7-4cf9-a441-06f375e00c7d |
2022-03-23T15:26:31+09:00 [INFO][PCF][Init] PCF Log level is set to [info] level
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:31+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:31+09:00 [INFO][PCF][CFG] config version [1.0.0]
2022-03-23T15:26:31+09:00 [INFO][PCF][Init] Server started
2022-03-23T15:26:31+09:00 [INFO][PCF][Util] pcfconfig Info: Version[1.0.0] Description[PCF initial local configuration]
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:31+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/c909a22c-848b-41f4-b023-e1fbbd7b48e4
2022-03-23T15:26:31+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/c909a22c-848b-41f4-b023-e1fbbd7b48e4 |
2022-03-23T15:26:31+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:31+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=PCF&service-names=nudr-dr&target-nf-type=UDR |
2022-03-23T15:26:32+09:00 [INFO][UDM][Init] UDM Log level is set to [info] level
2022-03-23T15:26:32+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:32+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:32+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:32+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:32+09:00 [INFO][UDM][CFG] config version [1.0.1]
2022-03-23T15:26:32+09:00 [INFO][UDM][Init] UDM Config Info: Version[1.0.1] Description[UDM initial local configuration]
2022-03-23T15:26:32+09:00 [INFO][UDM][Init] Server started
2022-03-23T15:26:32+09:00 [INFO][UDM][Util] udmconfig Info: Version[1.0.1] Description[UDM initial local configuration]
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/3986b4cd-a6f7-4c7a-9ee9-9e30e86ba049
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/3986b4cd-a6f7-4c7a-9ee9-9e30e86ba049 |
2022-03-23T15:26:32+09:00 [INFO][NSSF][Init] NSSF Log level is set to [info] level
2022-03-23T15:26:32+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:32+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:32+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:32+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:32+09:00 [INFO][NSSF][CFG] config version [1.0.0]
2022-03-23T15:26:32+09:00 [INFO][NSSF][Init] Server started
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/7f04a606-074a-43d8-821f-08d3808461f7
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/7f04a606-074a-43d8-821f-08d3808461f7 |
2022-03-23T15:26:32+09:00 [INFO][AUSF][Init] AUSF Log level is set to [info] level
2022-03-23T15:26:32+09:00 [INFO][LIB][Path] set log level : info
2022-03-23T15:26:32+09:00 [INFO][LIB][Path] set report call : false
2022-03-23T15:26:32+09:00 [INFO][LIB][OAPI] set log level : info
2022-03-23T15:26:32+09:00 [INFO][LIB][OAPI] set report call : false
2022-03-23T15:26:32+09:00 [INFO][AUSF][CFG] config version [1.0.0]
2022-03-23T15:26:32+09:00 [INFO][AUSF][Init] Server started
2022-03-23T15:26:32+09:00 [INFO][AUSF][Init] ausfconfig Info: Version[1.0.0] Description[AUSF initial local configuration]
ausf context =  &{{{0 0} {<nil>} map[] 0} {{0 0} {<nil>} map[] 0} 6a90d9e8-8c69-4782-a1dd-5f23adbe1be8 ausfGroup001 8000 127.0.0.9 127.0.0.9 http://127.0.0.9:8000 http http://127.0.0.10:8000 map[nausf-auth:{6a90d9e8-8c69-4782-a1dd-5f23adbe1be8 nausf-auth 0xc00060f940 http REGISTERED   0xc00060f920  [] <nil> [] [] <nil> 0 0 0 <nil> <nil> }] [{208 93} {123 45}]  0xc000207c20 false}
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Handle NFRegisterRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] urilist update
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Create NF Profile
2022-03-23T15:26:32+09:00 [INFO][NRF][MGMT] Location header:  http://127.0.0.10:8000/nnrf-nfm/v1/nf-instances/6a90d9e8-8c69-4782-a1dd-5f23adbe1be8
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 201 |       127.0.0.1 | PUT     | /nnrf-nfm/v1/nf-instances/6a90d9e8-8c69-4782-a1dd-5f23adbe1be8 |
=== RUN   TestPDUSessionReleaseRequest
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP] [AMF] SCTP Accept from: 127.0.0.1:9487
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP] Create a new NG connection for: 127.0.0.1:9487
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487] Handle NG Setup request
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487] Send NG-Setup response
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487] Handle Initial UE Message
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Handle Registration Request
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Authentication procedure
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=AUSF |
2022-03-23T15:26:32+09:00 [INFO][AUSF][UeAuthPost] HandleUeAuthPostRequest
2022-03-23T15:26:32+09:00 [INFO][AUSF][UeAuthPost] Serving network authorized
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=AUSF&service-names=nudm-ueau&target-nf-type=UDM |
2022-03-23T15:26:32+09:00 [INFO][UDM][UEAU] Handle GenerateAuthDataRequest
2022-03-23T15:26:32+09:00 [INFO][LIB][3GPP] suciPart: [suci 0 208 93 0 0 0 00007487]
2022-03-23T15:26:32+09:00 [INFO][LIB][3GPP] scheme 0
2022-03-23T15:26:32+09:00 [INFO][LIB][3GPP] SUPI type is IMSI
http://127.0.0.10:8000
2022/03/23 15:26:32 http2: server connection error from 127.0.0.1:33508: connection error: PROTOCOL_ERROR
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=UDM&target-nf-type=UDR |
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle QueryAuthSubsData
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/subscription-data/imsi-2089300007487/authentication-data/authentication-subscription |
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle ModifyAuthentication
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 204 |       127.0.0.1 | PATCH   | /nudr-dr/v1/subscription-data/imsi-2089300007487/authentication-data/authentication-subscription |
AUTN = 2443ac265896800063ea24780311b2f1
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 200 |       127.0.0.1 | POST    | /nudm-ueau/v1/suci-0-208-93-0-0-0-00007487/security-information/generate-auth-data |
2022-03-23T15:26:32+09:00 [INFO][AUSF][UeAuthPost] Add SuciSupiPair (suci-0-208-93-0-0-0-00007487, imsi-2089300007487) to map.
2022-03-23T15:26:32+09:00 [INFO][AUSF][UeAuthPost] Use 5G AKA auth method
2022-03-23T15:26:32+09:00 [INFO][AUSF][5gAkaAuth] XresStar = 3332313834656161383566306165323761303039663132383361353836396632
2022-03-23T15:26:32+09:00 [INFO][AUSF][GIN] | 201 |       127.0.0.1 | POST    | /nausf-auth/v1/ue-authentications |
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Send Authentication Request
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Handle Authentication Response
2022/03/23 15:26:32 http2: server connection error from 127.0.0.1:42508: connection error: PROTOCOL_ERROR
2022-03-23T15:26:32+09:00 [INFO][AUSF][5gAkaAuth] Auth5gAkaComfirmRequest
2022-03-23T15:26:32+09:00 [INFO][AUSF][5gAkaAuth] res*: 3332313834656161383566306165323761303039663132383361353836396632
Xres*: 3332313834656161383566306165323761303039663132383361353836396632
2022-03-23T15:26:32+09:00 [INFO][AUSF][5gAkaAuth] 5G AKA confirmation succeeded
2022-03-23T15:26:32+09:00 [INFO][UDM][UEAU] Handle ConfirmAuthDataRequest
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle CreateAuthenticationStatus
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 204 |       127.0.0.1 | PUT     | /nudr-dr/v1/subscription-data/imsi-2089300007487/authentication-data/authentication-status |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 201 |       127.0.0.1 | POST    | /nudm-ueau/v1/imsi-2089300007487/auth-events |
2022-03-23T15:26:32+09:00 [INFO][AUSF][GIN] | 200 |       127.0.0.1 | PUT     | /nausf-auth/v1/ue-authentications/suci-0-208-93-0-0-0-00007487/5g-aka-confirmation |
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Send Security Mode Command
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport
Security Header Type Integrity Protected With New 5g Nas Security Context
cmac value: 0x019f77c3
err <nil>
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle Security Mode Complete
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle InitialRegistration
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-2089300007487&target-nf-type=UDM |
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] Handle GetNssai
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle QueryAmData
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/am-data?supported-features= |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 200 |       127.0.0.1 | GET     | /nudm-sdm/v1/imsi-2089300007487/nssai?plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D |
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&supi=imsi-2089300007487&target-nf-type=UDM |
2022-03-23T15:26:32+09:00 [INFO][UDM][UECM] Handle RegistrationAmf3gppAccess
2022-03-23T15:26:32+09:00 [INFO][UDM][UECM] UEID: imsi-2089300007487
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle CreateAmfContext3gpp
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 204 |       127.0.0.1 | PUT     | /nudr-dr/v1/subscription-data/imsi-2089300007487/context-data/amf-3gpp-access |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 201 |       127.0.0.1 | PUT     | /nudm-uecm/v1/imsi-2089300007487/registrations/amf-3gpp-access |
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] Handle GetAmData
2022/03/23 15:26:32 http2: server connection error from 127.0.0.1:46260: connection error: PROTOCOL_ERROR
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle QueryAmData
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/am-data?supported-features=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 200 |       127.0.0.1 | GET     | /nudm-sdm/v1/imsi-2089300007487/am-data?plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D |
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] Handle GetSmfSelectData
2022/03/23 15:26:32 http2: server connection error from 127.0.0.1:46262: connection error: PROTOCOL_ERROR
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle QuerySmfSelectData
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/smf-selection-subscription-data?supported-features= |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 200 |       127.0.0.1 | GET     | /nudm-sdm/v1/imsi-2089300007487/smf-select-data?plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D |
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] Handle GetUeContextInSmfData
2022/03/23 15:26:32 http2: server connection error from 127.0.0.1:46264: connection error: PROTOCOL_ERROR
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle QuerySmfRegList
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/subscription-data/imsi-2089300007487/context-data/smf-registrations?supported-features= |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 200 |       127.0.0.1 | GET     | /nudm-sdm/v1/imsi-2089300007487/ue-context-in-smf-data |
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] Handle Subscribe
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle CreateSdmSubscriptions
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 201 |       127.0.0.1 | POST    | /nudr-dr/v1/subscription-data/imsi-2089300007487/context-data/sdm-subscriptions |
2022-03-23T15:26:32+09:00 [INFO][UDM][GIN] | 201 |       127.0.0.1 | POST    | /nudm-sdm/v1/imsi-2089300007487/sdm-subscriptions |
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?preferred-locality=area1&requester-nf-type=AMF&supi=imsi-2089300007487&target-nf-type=PCF |
2022-03-23T15:26:32+09:00 [INFO][PCF][Ampolicy] Handle AM Policy Create Request
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=PCF&target-nf-type=UDR |
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle PolicyDataUesUeIdAmDataGet
2022-03-23T15:26:32+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/policy-data/ues/imsi-2089300007487/am-data |
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?guami=%7B%22plmnId%22%3A%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D%2C%22amfId%22%3A%22cafe00%22%7D&requester-nf-type=PCF&target-nf-type=AMF |
2022-03-23T15:26:32+09:00 [INFO][AMF][Comm] Handle AMF Status Change Subscribe Request
2022-03-23T15:26:32+09:00 [INFO][AMF][Comm] new AMF Status Subscription[1]
2022-03-23T15:26:32+09:00 [INFO][AMF][GIN] | 201 |       127.0.0.1 | POST    | /namf-comm/v1/subscriptions |
2022-03-23T15:26:32+09:00 [INFO][PCF][GIN] | 201 |       127.0.0.1 | POST    | /npcf-am-policy-control/v1/policies |
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Send Registration Accept
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Send Initial Context Setup Request
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Handle Initial Context Setup Response
2022-03-23T15:26:32+09:00 [INFO][NAS][Message] Encode ExtendedProtocolConfigurationOptions in EncodePDUSessionEstablishmentRequest
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle Registration Complete
2022-03-23T15:26:32+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle UL NAS Transport
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Transport 5GSM Message to SMF
2022-03-23T15:26:32+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Select SMF [snssai: {Sst:1 Sd:010203}, dnn: internet]
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=AMF&target-nf-type=NSSF |
2022-03-23T15:26:32+09:00 [INFO][NSSF][NsSelect] Handle NSSelectionGet
2022-03-23T15:26:32+09:00 [INFO][NSSF][GIN] | 200 |       127.0.0.1 | GET     | /nnssf-nsselection/v1/network-slice-information?nf-id=2c395533-76ba-4a49-bf23-a3c5654d8099&nf-type=AMF&slice-info-request-for-pdu-session=%7B%22sNssai%22%3A%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D%2C%22roamingIndication%22%3A%22NON_ROAMING%22%7D |
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?dnn=internet&preferred-locality=area1&requester-nf-type=AMF&service-names=nsmf-pdusession&snssais=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D&target-nf-type=SMF&target-plmn-list=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D |
2022-03-23T15:26:32+09:00 [INFO][SMF][PduSess] Receive Create SM Context Request
2022-03-23T15:26:32+09:00 [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate
2022-03-23T15:26:32+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:32+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-type=UDM |
2022-03-23T15:26:32+09:00 [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully
2022-03-23T15:26:32+09:00 [INFO][SMF][CTX] Allocated UE IP address: 60.60.0.1
2022-03-23T15:26:32+09:00 [INFO][SMF][CTX] Selected UPF: UPF
2022-03-23T15:26:32+09:00 [INFO][SMF][PduSess] UE[imsi-2089300007487] PDUSessionID[10] IP[60.60.0.1]
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] Handle GetSmData
2022-03-23T15:26:32+09:00 [INFO][UDM][SDM] getSmDataProcedure: SUPI[imsi-2089300007487] PLMNID[20893] DNN[internet] SNssai[{"sst":1,"sd":"010203"}]
2022-03-23T15:26:32+09:00 [INFO][UDR][DRepo] Handle QuerySmData
2022-03-23T15:26:33+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/subscription-data/imsi-2089300007487/20893/provisioned-data/sm-data?single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D |
2022-03-23T15:26:33+09:00 [INFO][UDM][GIN] | 200 |       127.0.0.1 | GET     | /nudm-sdm/v1/imsi-2089300007487/sm-data?dnn=internet&plmn-id=%7B%22mcc%22%3A%22208%22%2C%22mnc%22%3A%2293%22%7D&single-nssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D |
2022-03-23T15:26:33+09:00 [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest
2022-03-23T15:26:33+09:00 [INFO][NAS][Convert] ProtocolOrContainerList:  [0xc000b70400 0xc000b70480 0xc000b70500]
2022-03-23T15:26:33+09:00 [INFO][SMF][GSM] Protocol Configuration Options
2022-03-23T15:26:33+09:00 [INFO][SMF][GSM] &{[0xc000b70400 0xc000b70480 0xc000b70500]}
2022-03-23T15:26:33+09:00 [INFO][SMF][GSM] Didn't Implement container type IPAddressAllocationViaNASSignallingUL
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-2089300007487] PDUSessionID[10]
2022-03-23T15:26:33+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:33+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?preferred-locality=area1&requester-nf-type=SMF&target-nf-type=PCF |
2022-03-23T15:26:33+09:00 [INFO][PCF][SMpolicy] Handle CreateSmPolicy
2022-03-23T15:26:33+09:00 [INFO][UDR][DRepo] Handle PolicyDataUesUeIdSmDataGet
2022-03-23T15:26:33+09:00 [INFO][UDR][GIN] | 200 |       127.0.0.1 | GET     | /nudr-dr/v1/policy-data/ues/imsi-2089300007487/sm-data?dnn=internet&snssai=%7B%22sst%22%3A1%2C%22sd%22%3A%22010203%22%7D |
2022-03-23T15:26:33+09:00 [INFO][PCF][GIN] | 201 |       127.0.0.1 | POST    | /npcf-smpolicycontrol/v1/sm-policies |
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] SUPI[imsi-2089300007487] has no pre-config route
2022-03-23T15:26:33+09:00 [INFO][NRF][DSCV] Handle NFDiscoveryRequest
2022-03-23T15:26:33+09:00 [INFO][NRF][GIN] | 200 |       127.0.0.1 | GET     | /nnrf-disc/v1/nf-instances?requester-nf-type=SMF&target-nf-instance-id=2c395533-76ba-4a49-bf23-a3c5654d8099&target-nf-type=AMF |
2022-03-23T15:26:33+09:00 [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok
2022-03-23T15:26:33+09:00 [INFO][SMF][GIN] | 201 |       127.0.0.1 | POST    | /nsmf-pdusession/v1/sm-contexts |
2022-03-23T15:26:33+09:00 [INFO][UPF][Util] [PFCP] Handle PFCP session establishment request
2022-03-23T15:26:33+09:00 [INFO][UPF][Util] [PFCP] Session Establishment Response
2022-03-23T15:26:33+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] create smContext[pduSessionID: 10] Success
2022-03-23T15:26:33+09:00 [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse
2022-03-23T15:26:33+09:00 [INFO][LIB][PFCP] Remove Request Transaction [2]
&{1000 Kbps 1000 Kbps}
2022-03-23T15:26:33+09:00 [INFO][AMF][Producer] Handle N1N2 Message Transfer Request
2022-03-23T15:26:33+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Send PDU Session Resource Setup Request
2022-03-23T15:26:33+09:00 [INFO][AMF][GIN] | 200 |       127.0.0.1 | POST    | /namf-comm/v1/ue-contexts/imsi-2089300007487/n1-n2-messages |
2022-03-23T15:26:33+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Handle PDU Session Resource Setup Response
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] Receive Update SM Context Request
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate
2022-03-23T15:26:33+09:00 [INFO][UPF][Util] [PFCP] Handle PFCP session modification request
2022-03-23T15:26:33+09:00 [INFO][UPF][Util] [PFCP] Session Modification Response
2022-03-23T15:26:33+09:00 [INFO][LIB][PFCP] Remove Request Transaction [3]
2022-03-23T15:26:33+09:00 [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept
2022-03-23T15:26:33+09:00 [INFO][SMF][PFCP] PFCP Session Modification Success[1]
2022-03-23T15:26:33+09:00 [INFO][SMF][GIN] | 200 |       127.0.0.1 | POST    | /nsmf-pdusession/v1/sm-contexts/urn:uuid:26a407d4-c8db-402c-a378-dc95c41acc8a/modify |
2022-03-23T15:26:33+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-03-23T15:26:33+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle UL NAS Transport
2022-03-23T15:26:33+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Transport 5GSM Message to SMF
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] Receive Update SM Context Request
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate
2022-03-23T15:26:33+09:00 [INFO][SMF][GSM] Handle Pdu Session Release Request
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] UE[imsi-2089300007487] PDUSessionID[10] Release IP[60.60.0.1]
2022-03-23T15:26:33+09:00 [INFO][PCF][SMpolicy] Handle DeleteSmPolicyContext
2022-03-23T15:26:33+09:00 [INFO][PCF][GIN] | 204 |       127.0.0.1 | POST    | /npcf-smpolicycontrol/v1/sm-policies/imsi-2089300007487-10/delete |
2022-03-23T15:26:33+09:00 [INFO][SMF][PduSess] Send PFCP Deletion from HandlePDUSessionSMContextUpdate
2022-03-23T15:26:33+09:00 [INFO][UPF][Util] [PFCP] Handle PFCP session deletion request
2022-03-23T15:26:33+09:00 [INFO][UPF][Util] [PFCP] Session Deletion Response
2022-03-23T15:26:33+09:00 [INFO][SMF][PFCP] Handle PFCP Session Deletion Response
2022-03-23T15:26:33+09:00 [INFO][LIB][PFCP] Remove Request Transaction [4]
2022-03-23T15:26:33+09:00 [INFO][SMF][PFCP] PFCP Session Deletion Success[1]
2022-03-23T15:26:33+09:00 [INFO][SMF][GIN] | 200 |       127.0.0.1 | POST    | /nsmf-pdusession/v1/sm-contexts/urn:uuid:26a407d4-c8db-402c-a378-dc95c41acc8a/modify |
2022-03-23T15:26:33+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Send PDU Session Resource Release Command
2022-03-23T15:26:34+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Handle PDU Session Resource Release Response
2022-03-23T15:26:34+09:00 [INFO][SMF][PduSess] Receive Update SM Context Request
2022-03-23T15:26:34+09:00 [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate
2022-03-23T15:26:34+09:00 [INFO][SMF][PduSess] [SMF] N2 PDUSession Release Complete
2022-03-23T15:26:34+09:00 [INFO][SMF][PduSess] [SMF] Send Update SmContext Response
2022-03-23T15:26:34+09:00 [INFO][SMF][GIN] | 200 |       127.0.0.1 | POST    | /nsmf-pdusession/v1/sm-contexts/urn:uuid:26a407d4-c8db-402c-a378-dc95c41acc8a/modify |
2022-03-23T15:26:35+09:00 [INFO][AMF][NGAP][127.0.0.1:9487][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 1)
2022-03-23T15:26:35+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Handle UL NAS Transport
2022-03-23T15:26:35+09:00 [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-2089300007487] Transport 5GSM Message to SMF
2022-03-23T15:26:35+09:00 [INFO][SMF][PduSess] Receive Update SM Context Request
2022-03-23T15:26:35+09:00 [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate
2022-03-23T15:26:35+09:00 [INFO][SMF][PduSess] [SMF] Send Update SmContext Response
2022-03-23T15:26:35+09:00 [INFO][SMF][CTX] [SMF] Send SMContext Status Notification
2022-03-23T15:26:35+09:00 [INFO][AMF][Producer] [AMF] Handle SmContext Status Notify
2022-03-23T15:26:35+09:00 [INFO][AMF][GIN] | 204 |       127.0.0.1 | POST    | /namf-callback/v1/smContextStatus/20893cafe0000000001/10 |
2022-03-23T15:26:35+09:00 [INFO][SMF][GIN] | 200 |       127.0.0.1 | POST    | /nsmf-pdusession/v1/sm-contexts/urn:uuid:26a407d4-c8db-402c-a378-dc95c41acc8a/modify |
2022-03-23T15:26:36+09:00 [INFO][AMF][NGAP] Handle SCTP Notification[addr: <nil>]
2022-03-23T15:26:36+09:00 [INFO][NRF][Init] Terminating NRF...
2022-03-23T15:26:36+09:00 [INFO][AMF][NGAP][127.0.0.1:9487] SCTP_SHUTDOWN_EVENT notification, close the connection
2022-03-23T15:26:36+09:00 [INFO][AMF][NGAP][127.0.0.1:9487] Remove RAN Context[ID: <PlmnID: {Mcc:208 Mnc:93}, GNbID: 000102>]
2022-03-23T15:26:36+09:00 [INFO][AMF][NGAP] Handle SCTP Notification[addr: <nil>]
2022-03-23T15:26:36+09:00 [INFO][NRF][Init] NRF terminated
2022-03-23T15:26:36+09:00 [WARN][AMF][NGAP] RAN context has been removed[addr: <nil>]
2022-03-23T15:26:36+09:00 [INFO][AMF][Init] Terminating AMF...
2022-03-23T15:26:36+09:00 [INFO][AMF][Consumer] [AMF] Send Deregister NFInstance
2022-03-23T15:26:36+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:37+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/2c395533-76ba-4a49-bf23-a3c5654d8099 |
2022-03-23T15:26:37+09:00 [INFO][AMF][Init] [AMF] Deregister from NRF successfully
2022-03-23T15:26:37+09:00 [INFO][AMF][Init] Send AMF Status Indication to Notify RANs due to AMF terminating
2022-03-23T15:26:37+09:00 [INFO][AMF][NGAP] Close SCTP server...
2022-03-23T15:26:37+09:00 [INFO][AMF][NGAP] SCTP server closed
2022-03-23T15:26:37+09:00 [INFO][AMF][Producer] [AMF] Send Amf Status Change Notify to http://127.0.0.7:8000/npcf-callback/v1/amfstatus
2022-03-23T15:26:37+09:00 [WARN][PCF][Callback] [PCF] Handle Amf Status Change Notify is not implemented.
2022-03-23T15:26:37+09:00 [INFO][PCF][GIN] | 204 |       127.0.0.1 | POST    | /npcf-callback/v1/amfstatus |
2022-03-23T15:26:37+09:00 [INFO][AMF][Init] AMF terminated
2022-03-23T15:26:37+09:00 [INFO][SMF][Init] Terminating SMF...
2022-03-23T15:26:37+09:00 [INFO][SMF][Consumer] Send Deregister NFInstance
2022-03-23T15:26:37+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:38+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/bd3eabc2-95b2-425a-aca5-3e14a36bf24f |
2022-03-23T15:26:38+09:00 [INFO][SMF][Init] Deregister from NRF successfully
2022-03-23T15:26:38+09:00 [INFO][UDR][Init] Terminating UDR...
2022-03-23T15:26:38+09:00 [INFO][UDR][Consumer] Send Deregister NFInstance
2022-03-23T15:26:38+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:39+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/e4eca06b-b5f7-4cf9-a441-06f375e00c7d |
2022-03-23T15:26:39+09:00 [INFO][UDR][Init] Deregister from NRF successfully
2022-03-23T15:26:39+09:00 [INFO][UDR][Init] UDR terminated
2022-03-23T15:26:39+09:00 [INFO][PCF][Init] Terminating PCF...
2022-03-23T15:26:39+09:00 [INFO][PCF][Consumer] Send Deregister NFInstance
2022-03-23T15:26:39+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:40+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/c909a22c-848b-41f4-b023-e1fbbd7b48e4 |
2022-03-23T15:26:40+09:00 [INFO][PCF][Init] Deregister from NRF successfully
2022-03-23T15:26:40+09:00 [INFO][PCF][Init] PCF terminated
2022-03-23T15:26:40+09:00 [INFO][UDM][Init] Terminating UDM...
2022-03-23T15:26:40+09:00 [INFO][UDM][Consumer] Send Deregister NFInstance
2022-03-23T15:26:40+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:41+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/3986b4cd-a6f7-4c7a-9ee9-9e30e86ba049 |
2022-03-23T15:26:41+09:00 [INFO][UDM][Init] Deregister from NRF successfully
2022-03-23T15:26:41+09:00 [INFO][UDM][Init] UDM terminated
2022-03-23T15:26:41+09:00 [INFO][NSSF][Init] Terminating NSSF...
2022-03-23T15:26:41+09:00 [INFO][NSSF][App] Send Deregister NFInstance
2022-03-23T15:26:41+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:42+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/7f04a606-074a-43d8-821f-08d3808461f7 |
2022-03-23T15:26:42+09:00 [INFO][NSSF][Init] Deregister from NRF successfully
2022-03-23T15:26:42+09:00 [INFO][NSSF][Init] NSSF terminated
2022-03-23T15:26:42+09:00 [INFO][AUSF][Init] Terminating AUSF...
2022-03-23T15:26:42+09:00 [INFO][AUSF][App] Send Deregister NFInstance
2022/03/23 15:26:42 http2: server connection error from 127.0.0.1:33596: connection error: PROTOCOL_ERROR
2022-03-23T15:26:42+09:00 [INFO][NRF][MGMT] Handle NFDeregisterRequest
2022-03-23T15:26:43+09:00 [INFO][NRF][GIN] | 204 |       127.0.0.1 | DELETE  | /nnrf-nfm/v1/nf-instances/6a90d9e8-8c69-4782-a1dd-5f23adbe1be8 |
2022-03-23T15:26:43+09:00 [INFO][AUSF][Init] Deregister from NRF successfully
2022-03-23T15:26:43+09:00 [INFO][AUSF][Init] AUSF terminated
--- PASS: TestPDUSessionReleaseRequest (10.53s)
PASS
ok      test    12.179s
2022-03-23T15:26:46+09:00 [INFO][UPF][Util] Removing DNN routes
22 packets captured
22 packets received by filter
0 packets dropped by kernel
2018 packets captured
4037 packets received by filter
0 packets dropped by kernel
nishi@GTP-U:~/free5gc-deb/free5gc$