search

free5gc / free5gc-compose

Apache License 2.0
137 stars 140 forks source link

[ERRO][SMF][PduSess] Handle PDUSessionResourceSetupResponseTransfer failed: Get bits overflow #61

Open minziran opened 2 years ago

minziran commented 2 years ago

Hi @abousselmi and @free5gc-org ,

I hope you are doing well. We are trying to connect the UE+ configured sim card to the Free5GC core. The UE is able to attach the NR5G, however, the amf and smf show some errors. I would appreciate any comments and help.

AMF log

root@free5gc5gtestbed-SIMATIC-IPC427E:/home/free5gc5gtestbed/free5gc-compose-amarisoft/config# sudo docker logs amf 2022-09-14T15:04:49Z [INFO][AMF][CFG] config version [1.0.3] 2022-09-14T15:04:49Z [INFO][AMF][Init] AMF Log level is set to [info] level 2022-09-14T15:04:49Z [INFO][LIB][NAS] set log level : info 2022-09-14T15:04:49Z [INFO][LIB][NAS] set report call : false 2022-09-14T15:04:49Z [INFO][LIB][NGAP] set log level : trace 2022-09-14T15:04:49Z [INFO][LIB][NGAP] set report call : false 2022-09-14T15:04:49Z [INFO][LIB][FSM] set log level : info 2022-09-14T15:04:49Z [INFO][LIB][FSM] set report call : false 2022-09-14T15:04:49Z [INFO][LIB][Aper] set log level : info 2022-09-14T15:04:49Z [INFO][LIB][Aper] set report call : false 2022-09-14T15:04:49Z [INFO][AMF][App] amf 2022-09-14T15:04:49Z [INFO][AMF][App] AMF version: free5GC version: v3.1.1 build time: 2022-05-25T14:32:37Z commit hash: 03f9848e commit time: 2022-04-07T14:37:30Z go version: go1.14.4 linux/amd64 2022-09-14T15:04:49Z [INFO][AMF][Init] Server started 2022-09-14T15:04:49Z [INFO][AMF][Util] amfconfig Info: Version[1.0.3] Description[AMF initial local configuration] 2022-09-14T15:04:49Z [INFO][AMF][NGAP] Listen on 10.100.200.13:38412 2022-09-14T15:04:53Z [INFO][AMF][NGAP] [AMF] SCTP Accept from: 192.168.137.234:54321 2022-09-14T15:04:53Z [INFO][AMF][NGAP] Create a new NG connection for: 192.168.137.234:54321 2022-09-14T15:04:53Z [INFO][AMF][NGAP][192.168.137.234:54321] Handle NG Setup request 2022-09-14T15:04:53Z [INFO][AMF][NGAP][192.168.137.234:54321] Send NG-Setup response 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321] Handle Initial UE Message 2022-09-14T15:06:22Z [INFO][LIB][FSM] Handle event[Gmm Message], transition from [Deregistered] to [Deregistered] 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Handle Registration Request 2022-09-14T15:06:22Z [INFO][LIB][FSM] Handle event[Start Authentication], transition from [Deregistered] to [Authentication] 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Authentication procedure 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Send Authentication Request 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 91) 2022-09-14T15:06:22Z [INFO][LIB][FSM] Handle event[Gmm Message], transition from [Authentication] to [Authentication] 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1] Handle Authentication Response 2022-09-14T15:06:22Z [INFO][LIB][FSM] Handle event[Authentication Success], transition from [Authentication] to [SecurityMode] 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] Send Security Mode Command 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 91) 2022-09-14T15:06:22Z [INFO][LIB][FSM] Handle event[Gmm Message], transition from [SecurityMode] to [SecurityMode] 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] Handle Security Mode Complete 2022-09-14T15:06:22Z [INFO][LIB][FSM] Handle event[SecurityMode Success], transition from [SecurityMode] to [ContextSetup] 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] Handle InitialRegistration 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] RequestedNssai - ServingSnssai: &{Sst:1 Sd:010203}, HomeSnssai: 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] RequestedNssai - ServingSnssai: &{Sst:1 Sd:112233}, HomeSnssai: 2022-09-14T15:06:22Z [INFO][AMF][Comm] Handle AMF Status Change Subscribe Request 2022-09-14T15:06:22Z [INFO][AMF][Comm] new AMF Status Subscription[1] 2022-09-14T15:06:22Z [INFO][AMF][GIN] | 201 | 10.100.200.9 | POST | /namf-comm/v1/subscriptions | 2022-09-14T15:06:22Z [INFO][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] Send Registration Accept 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Send Initial Context Setup Request 2022-09-14T15:06:22Z [WARN][AMF][NGAP][192.168.137.234:54321] Cause RadioNetwork[39] 2022-09-14T15:06:22Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Handle Initial Context Setup Failure 2022-09-14T15:06:28Z [WARN][AMF][GMM][AMF_UE_NGAP_ID:1][SUPI:imsi-001010000000012] T3550 expires, retransmit Registration Accept (retry: 1) 2022-09-14T15:06:28Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Send Downlink Nas Transport 2022-09-14T15:06:28Z [INFO][AMF][NGAP][192.168.137.234:54321][AMF_UE_NGAP_ID:1] Uplink NAS Transport (RAN UE NGAP ID: 91)

SMF log

root@free5gc5gtestbed-SIMATIC-IPC427E:/home/free5gc5gtestbed/free5gc-compose-amarisoft/config# sudo docker logs smf 2022-09-14T15:04:48Z [INFO][SMF][CFG] SMF config version [1.0.2] 2022-09-14T15:04:48Z [INFO][SMF][CFG] UE-Routing config version [1.0.1] 2022-09-14T15:04:48Z [INFO][SMF][Init] SMF Log level is set to [info] level 2022-09-14T15:04:48Z [INFO][LIB][NAS] set log level : info 2022-09-14T15:04:48Z [INFO][LIB][NAS] set report call : false 2022-09-14T15:04:48Z [INFO][LIB][NGAP] set log level : info 2022-09-14T15:04:48Z [INFO][LIB][NGAP] set report call : false 2022-09-14T15:04:48Z [INFO][LIB][Aper] set log level : info 2022-09-14T15:04:48Z [INFO][LIB][Aper] set report call : false 2022-09-14T15:04:48Z [INFO][LIB][PFCP] set log level : info 2022-09-14T15:04:48Z [INFO][LIB][PFCP] set report call : false 2022-09-14T15:04:48Z [INFO][SMF][App] smf 2022-09-14T15:04:48Z [INFO][SMF][App] SMF version: free5GC version: v3.1.1 build time: 2022-05-25T14:33:39Z commit hash: 84c979a3 commit time: 2022-04-09T08:38:26Z go version: go1.14.4 linux/amd64 2022-09-14T15:04:48Z [INFO][SMF][CTX] smfconfig Info: Version[1.0.2] Description[SMF initial local configuration] 2022-09-14T15:04:48Z [INFO][SMF][CTX] Endpoints: [upf.free5gc.org] 2022-09-14T15:04:48Z [INFO][SMF][Init] Server started 2022-09-14T15:04:48Z [INFO][SMF][Init] SMF Registration to NRF {a4f46490-3caf-490a-b5d1-3e2ef8ad24a0 SMF REGISTERED 0 0xc0002403a0 0xc0002403e0 [] [] [smf.free5gc.org] [] [] [] 0 0 0 area1 0xc000276b80 map[] false 0xc000240160 false false []} 2022-09-14T15:04:48Z [INFO][SMF][PFCP] Listen on 10.100.200.8:8805 2022-09-14T15:04:48Z [INFO][SMF][App] Send PFCP Association Request to UPFupf.free5gc.org 2022-09-14T15:04:48Z [INFO][LIB][PFCP] Remove Request Transaction [1] 2022-09-14T15:04:48Z [INFO][SMF][PFCP] In HandlePfcpAssociationSetupResponse 2022-09-14T15:04:48Z [INFO][SMF][PFCP] Handle PFCP Association Setup Response with NodeID[10.100.200.2] 2022-09-14T15:04:48Z [INFO][SMF][PFCP] UPF(10.100.200.2)[{internet}] setup association 2022-09-14T15:06:28Z [INFO][SMF][PduSess] Receive Create SM Context Request 2022-09-14T15:06:28Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-09-14T15:06:28Z [INFO][SMF][PduSess] Send NF Discovery Serving UDM Successfully 2022-09-14T15:06:28Z [INFO][SMF][CTX] Allocated UE IP address: 10.60.0.1 2022-09-14T15:06:28Z [INFO][SMF][CTX] Selected UPF: UPF 2022-09-14T15:06:28Z [INFO][SMF][PduSess] UE[imsi-001010000000012] PDUSessionID[1] IP[10.60.0.1] 2022-09-14T15:06:28Z [INFO][SMF][GSM] In HandlePDUSessionEstablishmentRequest 2022-09-14T15:06:28Z [INFO][NAS][Convert] ProtocolOrContainerList: [0xc00046e980 0xc00046e9e0 0xc00046ea20 0xc00046ea80 0xc00046eac0 0xc00046eb00 0xc00046eb40 0xc00046eb80] 2022-09-14T15:06:28Z [INFO][SMF][GSM] Protocol Configuration Options 2022-09-14T15:06:28Z [INFO][SMF][GSM] &{[0xc00046e980 0xc00046e9e0 0xc00046ea20 0xc00046ea80 0xc00046eac0 0xc00046eb00 0xc00046eb40 0xc00046eb80]} 2022-09-14T15:06:28Z [INFO][SMF][GSM] Didn't Implement container type InternetProtocolControlProtocolUL 2022-09-14T15:06:28Z [INFO][SMF][GSM] Didn't Implement container type IPAddressAllocationViaNASSignallingUL 2022-09-14T15:06:28Z [INFO][SMF][GSM] Didn't Implement container type MSSupportOfNetworkRequestedBearerControlIndicatorUL 2022-09-14T15:06:28Z [INFO][SMF][GSM] Didn't Implement container type MSSupportOfLocalAddressInTFTIndicatorUL 2022-09-14T15:06:28Z [INFO][SMF][GSM] Didn't Implement container type QoSRulesWithTheLengthOfTwoOctetsSupportIndicatorUL 2022-09-14T15:06:28Z [INFO][SMF][GSM] Didn't Implement container type QoSFlowDescriptionsWithTheLengthOfTwoOctetsSupportIndicatorUL 2022-09-14T15:06:28Z [INFO][SMF][PduSess] PCF Selection for SMContext SUPI[imsi-001010000000012] PDUSessionID[1] 2022-09-14T15:06:28Z [INFO][SMF][PduSess] SUPI[imsi-001010000000012] has no pre-config route 2022-09-14T15:06:28Z [INFO][SMF][Consumer] SendNFDiscoveryServingAMF ok 2022-09-14T15:06:28Z [INFO][SMF][GIN] | 201 | 10.100.200.13 | POST | /nsmf-pdusession/v1/sm-contexts | 2022-09-14T15:06:28Z [INFO][SMF][PFCP] In HandlePfcpSessionEstablishmentResponse 2022-09-14T15:06:28Z [INFO][LIB][PFCP] Remove Request Transaction [2] 2022-09-14T15:06:38Z [INFO][SMF][PduSess] Receive Update SM Context Request 2022-09-14T15:06:38Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-09-14T15:06:38Z [INFO][SMF][PFCP] In HandlePfcpSessionModificationResponse 2022-09-14T15:06:38Z [INFO][SMF][PduSess] [SMF] PFCP Modification Resonse Accept 2022-09-14T15:06:38Z [INFO][LIB][PFCP] Remove Request Transaction [3] 2022-09-14T15:06:38Z [INFO][SMF][PFCP] PFCP Session Modification Success[1] 2022-09-14T15:06:38Z [INFO][SMF][GIN] | 200 | 10.100.200.13 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:2c7adeaf-eaab-49f4-806c-a27e3914d70f/modify | 2022-09-14T15:06:38Z [INFO][SMF][PduSess] Receive Update SM Context Request 2022-09-14T15:06:38Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextUpdate 2022-09-14T15:06:38Z [ERRO][SMF][PduSess] Handle PDUSessionResourceSetupResponseTransfer failed: Get bits overflow, requireBits: 8, leftBits: 5 2022-09-14T15:06:38Z [WARN][SMF][PduSess] SM Context State [Active] shouldn't be here 2022-09-14T15:06:38Z [INFO][SMF][GIN] | 200 | 10.100.200.13 | POST | /nsmf-pdusession/v1/sm-contexts/urn:uuid:2c7adeaf-eaab-49f4-806c-a27e3914d70f/modify | 2022-09-14T15:08:01Z [INFO][SMF][PduSess] Receive Create SM Context Request 2022-09-14T15:08:01Z [INFO][SMF][PduSess] In HandlePDUSessionSMContextCreate 2022-09-14T15:08:01Z [INFO][LIB][PFCP] Remove Request Transaction [4] 2022-09-14T15:08:01Z [INFO][SMF][PFCP] Handle PFCP Session Deletion Response 2022-09-14T15:08:01Z [INFO][SMF][PFCP] PFCP Session Deletion Success[1] 2022-09-14T15:08:01Z [INFO][SMF][CTX] [SMF] Send SMContext Status Notification 2022-09-14T15:08:01Z [WARN][SMF][PduSess] Send SMContextStatus Notification Error[404 Not Found] 2022-09-14T15:08:01Z [WARN][SMF][PduSess] Send SMContext Status Notification Problem[&{Type: Title: Status:404 Detail:Guti[00101cafe0000000001] Not Found Instance: Cause:CONTEXT_NOT_FOUND InvalidParams:[]}] 2022-09-14T15:08:01Z [INFO][SMF][PduSess] UE[imsi-001010000000012] PDUSessionID[1] Release IP[10.60.0.1]

Best regards, Ziran

abousselmi commented 2 years ago

Hi @minziran

Can you please share a pcap trace on N2, N3 and N4? It can help understand the root cause.

Cheers,

minziran commented 2 years ago

Hi @minziran

Can you please share a pcap trace on N2, N3 and N4? It can help understand the root cause.

Cheers,

Hi @abousselmi,

Thank you for your quick reply. I have attached the trace log of AMF, SMF and UPF. https://github.com/minziran/Free5gcLogs

Best regards, Ziran