search

canonical / sdcore-amf-k8s-operator

Charmed Operator for the SD-Core Access and Mobility Management Function (AMF).
https://charmhub.io/sdcore-amf-k8s
Apache License 2.0
1 stars 1 forks source link

AMF panics when a UE tries to reconnect #472

Open ghislainbourgeois opened 3 days ago

ghislainbourgeois commented 3 days ago

Bug Description

I was testing with a Quectel module and was able to connect to the network with Ubuntu 24.04. I disconnected from the network, and a few minutes later tried to reconnect. However, the UE was not able to reconnect. While looking at the logs, the AMF is panicking during context setup.

The AMF did not crash and continued running afterwards, and by a quick look at things, it seems due to the fact that traces of the previous connection are still hold on to.

To Reproduce

Connect to the network with a Quectel module, disconnect, wait 2 minutes and try to reconnect.

Environment

Charmed Aether SD-Core 1.5/stable Juju 3.6.0 MicroK8s 1.31-strict Charmed OAI RAN

telco@juju-controller:~$ juju status -m control-plane
Model          Controller  Cloud/Region                     Version  SLA          Timestamp
control-plane  sdcore      control-plane-cluster/localhost  3.6.0    unsupported  16:52:16Z

SAAS          Status      Store  URL
cu            terminated  local  admin/oai.cu
loki          active      local  admin/cos-lite.loki
prometheus    active      local  admin/cos-lite.prometheus
upf-fiveg-n4  active      local  admin/user-plane.upf-fiveg-n4

App                       Version  Status  Scale  Charm                     Channel        Rev  Address         Exposed  Message
amf                       1.5.1    active      1  sdcore-amf-k8s            1.5/stable     834  10.152.183.224  no
ausf                      1.5.1    active      1  sdcore-ausf-k8s           1.5/stable     645  10.152.183.45   no
grafana-agent             0.32.1   active      1  grafana-agent-k8s         latest/stable   45  10.152.183.239  no
mongodb                            active      1  mongodb-k8s               6/stable        61  10.152.183.73   no
nms                       1.0.0    active      1  sdcore-nms-k8s            1.5/stable     741  10.152.183.128  no
nrf                       1.5.2    active      1  sdcore-nrf-k8s            1.5/stable     720  10.152.183.207  no
nssf                      1.5.1    active      1  sdcore-nssf-k8s           1.5/stable     614  10.152.183.179  no
pcf                       1.5.2    active      1  sdcore-pcf-k8s            1.5/stable     650  10.152.183.30   no
self-signed-certificates           active      1  self-signed-certificates  latest/stable  155  10.152.183.50   no
smf                       1.6.2    active      1  sdcore-smf-k8s            1.5/stable     745  10.152.183.155  no
traefik                   2.11.0   active      1  traefik-k8s               latest/stable  199  10.152.183.172  no       Serving at 10.5.5.53.nip.io
udm                       1.5.1    active      1  sdcore-udm-k8s            1.5/stable     605  10.152.183.77   no
udr                       1.6.1    active      1  sdcore-udr-k8s            1.5/stable     597  10.152.183.78   no
telco@juju-controller:~$ juju status -m user-plane
Model       Controller  Cloud/Region                  Version  SLA          Timestamp
user-plane  sdcore      user-plane-cluster/localhost  3.6.0    unsupported  16:52:54Z

SAAS        Status  Store  URL
loki        active  local  admin/cos-lite.loki
prometheus  active  local  admin/cos-lite.prometheus

App            Version  Status  Scale  Charm              Channel        Rev  Address        Exposed  Message
grafana-agent  0.32.1   active      1  grafana-agent-k8s  latest/stable   45  10.152.183.37  no
upf            1.5.0    active      1  sdcore-upf-k8s     1.5/stable     691  10.152.183.92  no
telco@juju-controller:~$ juju status -m oai
Model  Controller  Cloud/Region           Version  SLA          Timestamp
oai    sdcore      ran-cluster/localhost  3.6.0    unsupported  16:53:27Z

SAAS  Status  Store  URL
amf   active  local  admin/control-plane.amf
loki  active  local  admin/cos-lite.loki

App  Version  Status  Scale  Charm           Channel   Rev  Address        Exposed  Message
cu            active      1  oai-ran-cu-k8s  2.1/edge   39  10.152.183.81  no
du            active      1  oai-ran-du-k8s  2.1/edge   45  10.152.183.38  no

Relevant log output

Common labels: {"charm":"sdcore-amf-k8s","juju_application":"amf","juju_model":"control-plane","juju_model_uuid":"a82f7d2d-779d-4223-8fed-6c3a128e04da","juju_unit":"amf/0","pebble_service":"amf","product":"Juju"}
Line limit: "1000 (225 returned)"
Total bytes processed: "32.1  kB"

2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.073Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.073Z    INFO    ngap/handler.go:1437    handle Initial UE Message   {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.073Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.073Z    INFO    context/context.go:151  Allocate AmfUeNgapID : 9    {"component": "AMF", "category": "Context"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.075Z    INFO    nas_security/security.go:124    Security header type: Integrity Protected   {"component": "AMF", "category": "Comm"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.075Z    INFO    nas_security/security.go:152    UE Context derived from Suci: suci-0-001-01-0-0-0-0100007488    {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:8", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.075Z    INFO    nas/handler.go:68   Antype from new RanUe: 3GPP_ACCESS  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:18-05:00   2024-11-29T16:31:17.075Z    INFO    context/transaction.go:25   updated nashandler  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:20-05:00   2024-11-29T16:31:19.077Z    INFO    context/amf_ue.go:515   Detached UeContext from OldRanUe    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:8"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.164Z    ERROR   gmm/handler.go:1268 Registration Status Update Error[https://10.1.235.130:29518: server no response]    {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.164Z    WARN    nrfcache/nrfcache.go:152    cache miss for nftype AMF   {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.168Z    INFO    nrfcache/nrfcache.go:361    {5c5c9de7-af16-4cff-8a64-75786cde33e8 AMF REGISTERED 60 0xc00080a2b8 0xc00080a2d0 [] []   [10.1.235.130] [] <nil> [] [] <nil> 0 0 0  <nil> <nil> <nil> 0xc0000f4410 <nil> <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc00080a360 false false []}  {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.168Z    ERROR   callback/n1n2message.go:119 unsupported scheme[]{"component": "AMF", "category": "HTTP"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.168Z    INFO    nrfcache/match_filters.go:255   udm match found = true  {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.168Z    INFO    nrfcache/nrfcache.go:361    {cf42413c-e811-41aa-91c4-278cd25998d6 UDM REGISTERED 60 0xc0006f1e18 <nil> [] []   [10.1.235.138] [] <nil> [] [] <nil> 0 0 0  <nil> 0xc0002e9110 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc0006f1e30 false false []} {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.193Z    WARN    nrfcache/nrfcache.go:152    cache miss for nftype PCF   {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.196Z    INFO    nrfcache/nrfcache.go:361    {86023c9c-d7ce-4028-b24e-7430b29ecd53 PCF REGISTERED 60 0xc0008ce288 <nil> [] []   [10.1.235.142] [] <nil> [] [] <nil> 0 0 0  <nil> <nil> <nil> <nil> <nil> <nil> 0xc000ba4550 <nil> <nil> <nil> map[] <nil> false 0xc0008ce2a0 false false []} {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.211Z    INFO    producer/subscription.go:20 Handle AMF Status Change Subscribe Request  {"component": "AMF", "category": "Comm"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.212Z    INFO    producer/subscription.go:52 new AMF Status Subscription[1]  {"component": "AMF", "category": "Comm"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.212Z    INFO    logger/logger.go:92 | 201 |    10.1.235.142 | POST    | /namf-comm/v1/subscriptions |   {"component": "AMF", "category": "GIN"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.212Z    INFO    context/context.go:199  Supported Tai List in AMF Plmn: &{001 01}, Tac: 000001  {"component": "AMF", "category": "Context"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.213Z    INFO    message/send.go:272 send Registration Accept    {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.213Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.215Z    INFO    context/context.go:509  Guti found locally :  00101cafe0000000001   {"component": "AMF", "category": "Context"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.215Z    INFO    nas/handler.go:109  handle Nas Message  {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.215Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [ContextSetup] to [ContextSetup] {"component": "LIB", "category": "FSM"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.215Z    ERROR   gmm/sm.go:444   state mismatch: receieve gmm message[message type 0x41] at ContextSetup state   {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.215Z    ERROR   logger/logger.go:127    [Debugging] panic:
User-Agent: OpenAPI-Generator/1.0.0/gonamf-comm/v1/ue-contexts/5g-guti-00101cafe0000000001/transfer-update HTTP/2.0
2024-11-29T11:31:23-05:00   runtime error: invalid memory address or nil pointer dereference
2024-11-29T11:31:23-05:00   goroutine 146004 [running]:
2024-11-29T11:31:23-05:00   runtime/debug.Stack()
2024-11-29T11:31:23-05:00       /snap/go/10678/src/runtime/debug/stack.go:24 +0x5e
2024-11-29T11:31:23-05:00   github.com/omec-project/util/logger.NewGinWithZap.ginRecover.func2.1()
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/omec-project/util@v1.2.3/logger/logger.go:112 +0x117
2024-11-29T11:31:23-05:00   panic({0x120ee80?, 0x1fb88e0?})
2024-11-29T11:31:23-05:00       /snap/go/10678/src/runtime/panic.go:914 +0x21f
2024-11-29T11:31:23-05:00   github.com/omec-project/amf/producer.HandleRegistrationStatusUpdateRequest(0xc00052c9c0)
2024-11-29T11:31:23-05:00       /root/parts/amf/build/producer/ue_context.go:599 +0x38d
2024-11-29T11:31:23-05:00   github.com/omec-project/amf/communication.HTTPRegistrationStatusUpdate(0xc00082a900)
2024-11-29T11:31:23-05:00       /root/parts/amf/build/communication/api_individual_ue_context_document.go:189 +0x489
2024-11-29T11:31:23-05:00   github.com/gin-gonic/gin.(*Context).Next(0xc00082a900)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/context.go:185 +0x2b
2024-11-29T11:31:23-05:00   github.com/omec-project/util/logger.NewGinWithZap.ginRecover.func2(0xc00057b010?)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/omec-project/util@v1.2.3/logger/logger.go:142 +0x57
2024-11-29T11:31:23-05:00   github.com/gin-gonic/gin.(*Context).Next(0xc00082a900)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/context.go:185 +0x2b
2024-11-29T11:31:23-05:00   github.com/omec-project/util/logger.NewGinWithZap.ginToZap.func1(0xc00082a900)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/omec-project/util@v1.2.3/logger/logger.go:81 +0x5f
2024-11-29T11:31:23-05:00   github.com/gin-gonic/gin.(*Context).Next(...)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/context.go:185
2024-11-29T11:31:23-05:00   github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc000501a00, 0xc00082a900)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/gin.go:633 +0x892
2024-11-29T11:31:23-05:00   github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc000501a00, {0x165aa70?, 0xc000654070}, 0xc000794400)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/gin.go:589 +0x1dd
2024-11-29T11:31:23-05:00   golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP({{0x1650860?, 0xc000501a00?}, 0xc0006391f0?}, {0x165aa70, 0xc000654070}, 0xc000794400)
2024-11-29T11:31:23-05:00       /root/go/pkg/mod/golang.org/x/net@v0.30.0/http2/h2c/h2c.go:125 +0x699
2024-11-29T11:31:23-05:00   net/http.serverHandler.ServeHTTP({0x0?}, {0x165aa70?, 0xc000654070?}, 0x97ca11?)
2024-11-29T11:31:23-05:00       /snap/go/10678/src/net/http/server.go:2943 +0x8e
2024-11-29T11:31:23-05:00   net/http.initALPNRequest.ServeHTTP({{0x165e6b8?, 0xc0000f2d80?}, 0xc0006a9500?, {0xc00069e000?}}, {0x165aa70, 0xc000654070}, 0xc000794400)
2024-11-29T11:31:23-05:00       /snap/go/10678/src/net/http/server.go:3551 +0x231
2024-11-29T11:31:23-05:00   net/http.(*http2serverConn).runHandler(0x97c168?, 0xc000984000?, 0xc00098f5c0?, 0xc00098f4a0?)
2024-11-29T11:31:23-05:00       /snap/go/10678/src/net/http/h2_bundle.go:6232 +0xbb
2024-11-29T11:31:23-05:00   created by net/http.(*http2serverConn).scheduleHandler in goroutine 144268
2024-11-29T11:31:23-05:00       /snap/go/10678/src/net/http/h2_bundle.go:6167 +0x21d
2024-11-29T11:31:23-05:00       {"component": "AMF", "category": "GIN"}
2024-11-29T11:31:23-05:00   2024-11-29T16:31:22.215Z    INFO    logger/logger.go:92 | 500 |    10.1.235.130 | POST    | /namf-comm/v1/ue-contexts/5g-guti-00101cafe0000000001/transfer-update |     {"component": "AMF", "category": "GIN"}
2024-11-29T11:31:29-05:00   2024-11-29T16:31:28.216Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:35-05:00   2024-11-29T16:31:34.216Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.972Z    INFO    ngap/handler.go:2513    UE Context Release Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.972Z    WARN    ngap/handler.go:4689    Cause RadioNetwork[21]  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.972Z    INFO    message/send.go:209 send UE Context Release Command {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:8"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.973Z    WARN    message/send.go:82  AmfUe is nil    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:8"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.976Z    INFO    ngap/handler.go:925 handle UE Context Release Complete  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.976Z    INFO    ngap/handler.go:984 Release UE Context : RanUe[AmfUeNgapId: 8]  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:37-05:00   2024-11-29T16:31:36.976Z    INFO    context/ran_ue.go:87    RanUe has been deleted  {"component": "AMF", "category": "Context"}
2024-11-29T11:31:41-05:00   2024-11-29T16:31:40.217Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.063Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.064Z    INFO    ngap/handler.go:1437    handle Initial UE Message   {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.064Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.064Z    INFO    context/context.go:151  Allocate AmfUeNgapID : 10   {"component": "AMF", "category": "Context"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.065Z    INFO    nas_security/security.go:124    Security header type: Integrity Protected   {"component": "AMF", "category": "Comm"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.065Z    INFO    nas_security/security.go:152    UE Context derived from Suci: suci-0-001-01-0-0-0-0100007488    {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.065Z    INFO    nas/handler.go:68   Antype from new RanUe: 3GPP_ACCESS  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.066Z    INFO    context/transaction.go:25   updated nashandler  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.066Z    INFO    nas/handler.go:109  handle Nas Message  {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.066Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [ContextSetup] to [ContextSetup] {"component": "LIB", "category": "FSM"}
2024-11-29T11:31:43-05:00   2024-11-29T16:31:42.066Z    ERROR   gmm/sm.go:444   state mismatch: receieve gmm message[message type 0x41] at ContextSetup state   {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:31:45-05:00   2024-11-29T16:31:44.068Z    INFO    context/amf_ue.go:515   Detached UeContext from OldRanUe    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:31:47-05:00   2024-11-29T16:31:46.216Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:31:53-05:00   2024-11-29T16:31:52.215Z    WARN    message/send.go:306 T3550 Expires 4 times, abort retransmission of Registration Accept  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.972Z    INFO    ngap/handler.go:2513    UE Context Release Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.972Z    WARN    ngap/handler.go:4689    Cause RadioNetwork[21]  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.972Z    INFO    message/send.go:209 send UE Context Release Command {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.973Z    WARN    message/send.go:82  AmfUe is nil    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:9"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.977Z    INFO    ngap/handler.go:925 handle UE Context Release Complete  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.977Z    INFO    ngap/handler.go:984 Release UE Context : RanUe[AmfUeNgapId: 9]  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:02-05:00   2024-11-29T16:32:01.977Z    INFO    context/ran_ue.go:87    RanUe has been deleted  {"component": "AMF", "category": "Context"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.073Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.073Z    INFO    ngap/handler.go:1437    handle Initial UE Message   {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.073Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.073Z    INFO    context/context.go:151  Allocate AmfUeNgapID : 11   {"component": "AMF", "category": "Context"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.074Z    INFO    nas_security/security.go:124    Security header type: Integrity Protected   {"component": "AMF", "category": "Comm"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    nas_security/security.go:152    UE Context derived from Suci: suci-0-001-01-0-0-0-0100007488    {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    nas/handler.go:68   Antype from new RanUe: 3GPP_ACCESS  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    context/transaction.go:25   updated nashandler  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    nas/handler.go:109  handle Nas Message  {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [Registered] to [Registered] {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    gmm/handler.go:393  Handle Registration Request{"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    fsm/fsm.go:99   handle event[Start Authentication], transition from [Registered] to [Authentication]    {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    ERROR   metrics/kafka.go:80 could not publish ue context event, error [dial tcp: lookup sd-core-kafka-headless on 10.152.183.10:53: no such host]   {"component": "AMF", "category": "Kafka"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.075Z    INFO    gmm/handler.go:1509 Authentication procedure    {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.076Z    INFO    nrfcache/match_filters.go:146   ausf match found = true {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.076Z    INFO    nrfcache/nrfcache.go:361    {49fd870f-a105-4026-8f9c-1c2cfc3db3b9 AUSF REGISTERED 60 0xc000aa0258 <nil> [] []   [10.1.235.191] [] <nil> [] [] <nil> 0 0 0  <nil> <nil> 0xc00088ce80 <nil> <nil> <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc000aa0270 false false []}    {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.092Z    INFO    message/send.go:80  send Authentication Request{"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.092Z    INFO    message/send.go:171 send Downlink Nas Transport{"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.103Z    INFO    ngap/dispatcher.go:144  Uecontext found. queuing ngap message to uechannel  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.103Z    INFO    context/transaction.go:20   updated ngaphandler{"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    INFO    ngap/handler.go:686 handle Uplink Nas Transport{"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    INFO    ngap/handler.go:740 Uplink NAS Transport (RAN UE NGAP ID: 3)    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [Authentication] to [Authentication] {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    INFO    gmm/handler.go:2178 Handle Authentication Failure   {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    WARN    gmm/handler.go:2198 Authentication Failure Cause: NgKSI Already In Use  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    WARN    gmm/handler.go:2200 Select new NgKsi    {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    INFO    message/send.go:80  send Authentication Request{"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.104Z    INFO    message/send.go:171 send Downlink Nas Transport{"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.153Z    INFO    ngap/dispatcher.go:144  Uecontext found. queuing ngap message to uechannel  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.153Z    INFO    context/transaction.go:20   updated ngaphandler{"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.153Z    INFO    ngap/handler.go:686 handle Uplink Nas Transport{"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.153Z    INFO    ngap/handler.go:740 Uplink NAS Transport (RAN UE NGAP ID: 3)    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.154Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [Authentication] to [Authentication] {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.154Z    INFO    gmm/handler.go:2052 Handle Authentication Response  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.168Z    INFO    fsm/fsm.go:99   handle event[Authentication Success], transition from [Authentication] to [SecurityMode]    {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.168Z    ERROR   metrics/kafka.go:80 could not publish ue context event, error [dial tcp: lookup sd-core-kafka-headless on 10.152.183.10:53: no such host]   {"component": "AMF", "category": "Kafka"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.168Z    INFO    message/send.go:188 send Security Mode Command  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.169Z    INFO    message/send.go:171 send Downlink Nas Transport{"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.169Z    ERROR   metrics/kafka.go:80 could not publish ue context event, error [dial tcp: lookup sd-core-kafka-headless on 10.152.183.10:53: no such host]   {"component": "AMF", "category": "Kafka"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.183Z    INFO    ngap/dispatcher.go:144  Uecontext found. queuing ngap message to uechannel  {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "supi": "SUPI:imsi-001010100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.183Z    INFO    context/transaction.go:20   updated ngaphandler{"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "supi": "SUPI:imsi-001010100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.183Z    INFO    ngap/handler.go:686 handle Uplink Nas Transport{"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.183Z    INFO    ngap/handler.go:740 Uplink NAS Transport (RAN UE NGAP ID: 3)    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.183Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [SecurityMode] to [SecurityMode] {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.184Z    INFO    gmm/handler.go:2287 Handle Security Mode Complete   {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.184Z    INFO    fsm/fsm.go:99   handle event[SecurityMode Success], transition from [SecurityMode] to [ContextSetup]    {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.184Z    ERROR   metrics/kafka.go:80 could not publish ue context event, error [dial tcp: lookup sd-core-kafka-headless on 10.152.183.10:53: no such host]   {"component": "AMF", "category": "Kafka"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.184Z    INFO    gmm/handler.go:583  Handle InitialRegistration  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.184Z    INFO    nrfcache/match_filters.go:255   udm match found = true  {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.184Z    INFO    nrfcache/nrfcache.go:361    {cf42413c-e811-41aa-91c4-278cd25998d6 UDM REGISTERED 60 0xc0006f1e18 <nil> [] []   [10.1.235.138] [] <nil> [] [] <nil> 0 0 0  <nil> 0xc0002e9110 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc0006f1e30 false false []} {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.189Z    INFO    gmm/handler.go:1216 RequestedNssai: [{ServingSnssai:0xc000b900c0 HomeSnssai:<nil>}] {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "suci": "suci-0-001-01-0-0-0-0100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.191Z    INFO    producer/ue_context.go:569  Handle Registration Status Update Request   {"component": "AMF", "category": "Comm"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.191Z    INFO    context/context.go:509  Guti found locally :  00101cafe0000000001   {"component": "AMF", "category": "Context"}
2024-11-29T11:32:08-05:00   2024-11-29T16:32:07.191Z    INFO    context/transaction.go:30   updated sbihandler  {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "supi": "SUPI:imsi-001010100007488", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:10-05:00   2024-11-29T16:32:09.076Z    INFO    context/amf_ue.go:515   Detached UeContext from OldRanUe    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.972Z    INFO    ngap/handler.go:2513    UE Context Release Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.972Z    WARN    ngap/handler.go:4689    Cause RadioNetwork[21]  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.972Z    INFO    message/send.go:209 send UE Context Release Command {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.973Z    WARN    message/send.go:82  AmfUe is nil    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:10"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.974Z    INFO    ngap/handler.go:925 handle UE Context Release Complete  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.975Z    INFO    ngap/handler.go:984 Release UE Context : RanUe[AmfUeNgapId: 10] {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:27-05:00   2024-11-29T16:32:26.975Z    INFO    context/ran_ue.go:87    RanUe has been deleted  {"component": "AMF", "category": "Context"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.263Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.263Z    INFO    ngap/handler.go:1437    handle Initial UE Message   {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.263Z    INFO    context/amf_ran.go:127  RanUe does not exist    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.263Z    INFO    context/context.go:151  Allocate AmfUeNgapID : 12   {"component": "AMF", "category": "Context"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.265Z    INFO    nas_security/security.go:124    Security header type: Integrity Protected   {"component": "AMF", "category": "Comm"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.265Z    INFO    nas_security/security.go:152    UE Context derived from Suci: suci-0-001-01-0-0-0-0100007488    {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11", "supi": "SUPI:imsi-001010100007488"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.265Z    INFO    nas/handler.go:68   Antype from new RanUe: 3GPP_ACCESS  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:33-05:00   2024-11-29T16:32:32.265Z    INFO    context/transaction.go:25   updated nashandler  {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:35-05:00   2024-11-29T16:32:34.267Z    INFO    context/amf_ue.go:515   Detached UeContext from OldRanUe    {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:11"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.191Z    ERROR   gmm/handler.go:1268 Registration Status Update Error[https://10.1.235.130:29518: server no response]    {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.191Z    INFO    nrfcache/match_filters.go:233   amf match found = 5c5c9de7-af16-4cff-8a64-75786cde33e8  {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.191Z    INFO    nrfcache/nrfcache.go:361    {5c5c9de7-af16-4cff-8a64-75786cde33e8 AMF REGISTERED 60 0xc00080a2b8 0xc00080a2d0 [] []   [10.1.235.130] [] <nil> [] [] <nil> 0 0 0  <nil> <nil> <nil> 0xc0000f4410 <nil> <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc00080a360 false false []}  {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.191Z    ERROR   callback/n1n2message.go:119 unsupported scheme[]{"component": "AMF", "category": "HTTP"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.191Z    WARN    nrfcache/nrfcache.go:152    cache miss for nftype UDM   {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.195Z    INFO    nrfcache/nrfcache.go:361    {cf42413c-e811-41aa-91c4-278cd25998d6 UDM REGISTERED 60 0xc000aa0978 <nil> [] []   [10.1.235.138] [] <nil> [] [] <nil> 0 0 0  <nil> 0xc0002d6070 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil> map[] <nil> false 0xc000aa0990 false false []} {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.220Z    INFO    nrfcache/match_filters.go:244   pcf match found = true  {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.221Z    INFO    nrfcache/nrfcache.go:361    {86023c9c-d7ce-4028-b24e-7430b29ecd53 PCF REGISTERED 60 0xc0008ce288 <nil> [] []   [10.1.235.142] [] <nil> [] [] <nil> 0 0 0  <nil> <nil> <nil> <nil> <nil> <nil> 0xc000ba4550 <nil> <nil> <nil> map[] <nil> false 0xc0008ce2a0 false false []} {"component": "LIB", "category": "Nrfcache"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.227Z    INFO    context/context.go:199  Supported Tai List in AMF Plmn: &{001 01}, Tac: 000001  {"component": "AMF", "category": "Context"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.227Z    INFO    message/send.go:272 send Registration Accept    {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.227Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.229Z    INFO    context/context.go:509  Guti found locally :  00101cafe0000000001   {"component": "AMF", "category": "Context"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.229Z    INFO    nas/handler.go:109  handle Nas Message  {"component": "AMF", "category": "NAS", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.230Z    INFO    fsm/fsm.go:99   handle event[Gmm Message], transition from [ContextSetup] to [ContextSetup] {"component": "LIB", "category": "FSM"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.230Z    ERROR   gmm/sm.go:444   state mismatch: receieve gmm message[message type 0x41] at ContextSetup state   {"component": "AMF", "category": "GMM", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.230Z    ERROR   logger/logger.go:127    [Debugging] panic:
User-Agent: OpenAPI-Generator/1.0.0/gonamf-comm/v1/ue-contexts/5g-guti-00101cafe0000000001/transfer-update HTTP/2.0
2024-11-29T11:32:38-05:00   runtime error: invalid memory address or nil pointer dereference
2024-11-29T11:32:38-05:00   goroutine 146438 [running]:
2024-11-29T11:32:38-05:00   runtime/debug.Stack()
2024-11-29T11:32:38-05:00       /snap/go/10678/src/runtime/debug/stack.go:24 +0x5e
2024-11-29T11:32:38-05:00   github.com/omec-project/util/logger.NewGinWithZap.ginRecover.func2.1()
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/omec-project/util@v1.2.3/logger/logger.go:112 +0x117
2024-11-29T11:32:38-05:00   panic({0x120ee80?, 0x1fb88e0?})
2024-11-29T11:32:38-05:00       /snap/go/10678/src/runtime/panic.go:914 +0x21f
2024-11-29T11:32:38-05:00   github.com/omec-project/amf/producer.HandleRegistrationStatusUpdateRequest(0xc00069d050)
2024-11-29T11:32:38-05:00       /root/parts/amf/build/producer/ue_context.go:599 +0x38d
2024-11-29T11:32:38-05:00   github.com/omec-project/amf/communication.HTTPRegistrationStatusUpdate(0xc000794000)
2024-11-29T11:32:38-05:00       /root/parts/amf/build/communication/api_individual_ue_context_document.go:189 +0x489
2024-11-29T11:32:38-05:00   github.com/gin-gonic/gin.(*Context).Next(0xc000794000)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/context.go:185 +0x2b
2024-11-29T11:32:38-05:00   github.com/omec-project/util/logger.NewGinWithZap.ginRecover.func2(0xc000727160?)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/omec-project/util@v1.2.3/logger/logger.go:142 +0x57
2024-11-29T11:32:38-05:00   github.com/gin-gonic/gin.(*Context).Next(0xc000794000)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/context.go:185 +0x2b
2024-11-29T11:32:38-05:00   github.com/omec-project/util/logger.NewGinWithZap.ginToZap.func1(0xc000794000)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/omec-project/util@v1.2.3/logger/logger.go:81 +0x5f
2024-11-29T11:32:38-05:00   github.com/gin-gonic/gin.(*Context).Next(...)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/context.go:185
2024-11-29T11:32:38-05:00   github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc000501a00, 0xc000794000)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/gin.go:633 +0x892
2024-11-29T11:32:38-05:00   github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc000501a00, {0x165aa70?, 0xc000654310}, 0xc00050cb00)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/github.com/gin-gonic/gin@v1.10.0/gin.go:589 +0x1dd
2024-11-29T11:32:38-05:00   golang.org/x/net/http2/h2c.h2cHandler.ServeHTTP({{0x1650860?, 0xc000501a00?}, 0xc0006391f0?}, {0x165aa70, 0xc000654310}, 0xc00050cb00)
2024-11-29T11:32:38-05:00       /root/go/pkg/mod/golang.org/x/net@v0.30.0/http2/h2c/h2c.go:125 +0x699
2024-11-29T11:32:38-05:00   net/http.serverHandler.ServeHTTP({0x5573fe?}, {0x165aa70?, 0xc000654310?}, 0x97cca7?)
2024-11-29T11:32:38-05:00       /snap/go/10678/src/net/http/server.go:2943 +0x8e
2024-11-29T11:32:38-05:00   net/http.initALPNRequest.ServeHTTP({{0x165e6b8?, 0xc0000f2d80?}, 0xc0006a9500?, {0xc00069e000?}}, {0x165aa70, 0xc000654310}, 0xc00050cb00)
2024-11-29T11:32:38-05:00       /snap/go/10678/src/net/http/server.go:3551 +0x231
2024-11-29T11:32:38-05:00   net/http.(*http2serverConn).runHandler(0x97c168?, 0xc0009be300?, 0x6014c7?, 0x0?)
2024-11-29T11:32:38-05:00       /snap/go/10678/src/net/http/h2_bundle.go:6232 +0xbb
2024-11-29T11:32:38-05:00   created by net/http.(*http2serverConn).scheduleHandler in goroutine 144268
2024-11-29T11:32:38-05:00       /snap/go/10678/src/net/http/h2_bundle.go:6167 +0x21d
2024-11-29T11:32:38-05:00       {"component": "AMF", "category": "GIN"}
2024-11-29T11:32:38-05:00   2024-11-29T16:32:37.230Z    INFO    logger/logger.go:92 | 500 |    10.1.235.130 | POST    | /namf-comm/v1/ue-contexts/5g-guti-00101cafe0000000001/transfer-update |     {"component": "AMF", "category": "GIN"}
2024-11-29T11:32:44-05:00   2024-11-29T16:32:43.231Z    INFO    message/send.go:375 send Initial Context Setup Request  {"component": "AMF", "category": "NGAP", "ran_addr": "10.5.5.4:14029", "amf_ue_ngap_id": "AMF_UE_NGAP_ID:12"}

Additional context

No response

ghislainbourgeois commented 3 days ago

Waiting an hour before reconnecting gives the same error.