"Received a termination request from Access" 5 seconds after connect #15298

FrankPetrilli · 2023-08-30T23:29:49Z

FrankPetrilli
Aug 30, 2023

Hey all!

I'm presently trying to move a functional small Magma setup to a new machine, but I'm running into a funky bit of behavior late in the connection establishment process on my new instances.

Setup

My setup is as follows, and has worked with previous versions of Magma:

Magma AGW on Ubuntu 20.04 installed from https://github.com/magma/magma/raw/v1.8/lte/gateway/deploy/agw_install_ubuntu.sh
Endless AGW crashloop, mme exiting on start with Sanitizer CHECK failed #15279 (comment) applied as a fix
Baicells Nova 227

What's happening

Approximately 5 seconds after establishment, sessiond terminates the UE's session due to Received a termination request from Access for IMSI315010461196449 apn internet. The UE shows a connection briefly before disconnecting. The same setup has worked previously.

Logs

Aug 30 22:55:16 magma-agw mme[3453]: [DEBUG] Success logging event: s1_setup_success
Aug 30 22:55:16 magma-agw sctpd[3329]: I0830 22:55:16.030835  3526 sctp_connection.cpp:208] Unhandled notification type 32777
Aug 30 22:55:16 magma-agw sctpd[3329]: I0830 22:55:16.321300  3526 sctp_connection.cpp:208] Unhandled notification type 32777
Aug 30 22:55:16 magma-agw directoryd[1642]: INFO:redis_lock.acquire:Got lock for 'lock:IMSI:directory_record:lock'.
Aug 30 22:55:16 magma-agw mme[3453]: Directoryd RPC failed with code 5, msg: Record for ID IMSI was not found.
Aug 30 22:55:16 magma-agw mme[3453]: [INFO] Sending S6A-AUTHENTICATION_INFORMATION_REQUEST with IMSI: 315010461196449
Aug 30 22:55:16 magma-agw subscriberdb[7706]: INFO:root:Auth success: 315010461196449
Aug 30 22:55:16 magma-agw mme[3453]: [INFO] Received S6A-AUTHENTICATION_INFORMATION_ANSWER for IMSI: 315010461196449; Status: ; StatusCode: 2001
Aug 30 22:55:16 magma-agw sctpd[3329]: I0830 22:55:16.667443  3526 sctp_connection.cpp:208] Unhandled notification type 32777
Aug 30 22:55:16 magma-agw sctpd[3329]: I0830 22:55:16.707769  3526 sctp_connection.cpp:208] Unhandled notification type 32777
Aug 30 22:55:16 magma-agw mme[3453]: [DEBUG] Sending S6A-UPDATE_LOCATION_REQUEST with IMSI: 315010461196449
Aug 30 22:55:16 magma-agw mme[3453]: [INFO] Received S6A-LOCATION-UPDATE_ANSWER for IMSI: 315010461196449; Status: ; StatusCode: 2001
Aug 30 22:55:16 magma-agw mme[3453]: [INFO] sent itti S6A-LOCATION-UPDATE_ANSWER for IMSI: 315010461196449
Aug 30 22:55:16 magma-agw mobilityd[3351]: INFO:root:Allocated IP 10.128.0.14 for sid IMSI315010461196449 for apn internet
Aug 30 22:55:16 magma-agw sessiond[3344]: I0830 22:55:16.721071  3344 LocalSessionManagerHandler.cpp:706] Received a LocalCreateSessionRequest for IMSI315010461196449 with APN:internet, default bearer ID:5, PLMN ID:31099, IMSI PLMN ID:31501, User location: 82 13 f0 99 00 01 13 f0 99 04 66 cf cf
Aug 30 22:55:16 magma-agw sessiond[3344]: I0830 22:55:16.722033  3344 LocalSessionManagerHandler.cpp:342] Initializing IMSI315010461196449-943736 in SessionStore before sending a CreateSessionRequest
Aug 30 22:55:16 magma-agw sessiond[3344]: I0830 22:55:16.722641  3344 LocalSessionManagerHandler.cpp:360] Sending a CreateSessionRequest to fetch policies for IMSI315010461196449-943736
Aug 30 22:55:16 magma-agw policydb[1724]: INFO:root:Creating a session for subscriber ID: IMSI315010461196449
Aug 30 22:55:16 magma-agw sessiond[3344]: I0830 22:55:16.725872  3344 LocalSessionManagerHandler.cpp:370] Processing CreateSessionResponse for IMSI315010461196449-943736
Aug 30 22:55:16 magma-agw sessiond[3344]: I0830 22:55:16.726980  3344 LocalSessionManagerHandler.cpp:403] Successfully initialized IMSI315010461196449-943736 in SessionD after talking to PolicyDB/SessionProxy
Aug 30 22:55:16 magma-agw sessiond[3344]: I0830 22:55:16.727012  3344 LocalSessionManagerHandler.cpp:528] Sending a request to DirectoryD to register sessiond ID: IMSI315010461196449-943736 msisdn:
Aug 30 22:55:16 magma-agw directoryd[1642]: INFO:redis_lock.acquire:Got lock for 'lock:IMSI315010461196449:directory_record:lock'.
Aug 30 22:55:16 magma-agw sctpd[3329]: I0830 22:55:16.802054  3526 sctp_connection.cpp:208] Unhandled notification type 32777
Aug 30 22:55:16 magma-agw smsd[1778]: INFO:root:mme non_eps_service_config is not SMS_ORC8R, sleeping.
Aug 30 22:55:20 magma-agw mme[3453]: [DEBUG] Success logging event: detach_success
Aug 30 22:55:20 magma-agw sessiond[3344]: I0830 22:55:20.734140  3344 LocalSessionManagerHandler.cpp:561] Received a termination request from Access for IMSI315010461196449 apn internet
Aug 30 22:55:20 magma-agw sessiond[3344]: I0830 22:55:20.734190  3344 LocalEnforcer.cpp:555] Initiating session termination for IMSI315010461196449-943736
Aug 30 22:55:20 magma-agw mobilityd[3351]: INFO:root:Released IP 10.128.0.14 for sid IMSI315010461196449
Aug 30 22:55:20 magma-agw sctpd[3329]: I0830 22:55:20.741429  3526 sctp_connection.cpp:208] Unhandled notification type 32777

Packet Capture

Answered by FrankPetrilli

Sep 19, 2023

Hey all,

Oddly enough, in spite of setting reduced MTUs, etc, this was resolved by removing the IPSec tunnel from the picture and putting the two directly adjacent in layer-3 space. Something to be looked at so the IPSec transport use case can be looked into for the future, but for now I'll close this issue.

View full answer

prabinakpattnaik · 2023-08-31T19:05:23Z

prabinakpattnaik
Aug 31, 2023
Maintainer

Please share the MME logs with log level as DEBUG.

0 replies

panyogesh · 2023-09-01T02:13:58Z

panyogesh
Sep 1, 2023
Maintainer

As @prabinakpattnaik , it will be good to have the mme.logs. Few observations I can see:

"sctp_connection.cpp:208] Unhandled notification type 32777" : Something on similar lines got fixed in latest master.
Packet-15 Sack Data Message fragment. Can you just check whether settings are all fine.

It will be great if it can be tested on latest master and share mme.logs in case of issues.

0 replies

FrankPetrilli · 2023-09-06T16:42:33Z

FrankPetrilli
Sep 6, 2023
Author

Hey all,

In spite of enabling a bunch of DEBUG log settings, it looks like mmed still logs in only INFO. Regardless, I got some useful logs, which I've attached. They seem to indicate a timeout to receive the InitialContextSetupResponse, which can be clearly seen in the pcap (albeit fragmented). My setup does pass over an IPSec tunnel, but the MTU should be more than enough to accommodate, and I've decreased the MTU on the eNodeB to 1400.

Normal setup

001442 Wed Sep 06 16:31:39 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0109    Received S1AP INITIAL_UE_MESSAGE ENB_UE_S1AP_ID 70 assoc-id:16
001443 Wed Sep 06 16:31:39 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0132    New Initial UE message received with eNB UE S1AP ID: 70 assoc-id :16
001444 Wed Sep 06 16:31:39 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_itti_messagi:0166    Sending Initial UE Message to MME_APP, enb_ue_s1ap_id : 70
001445 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :0632    Received MME_APP_INITIAL_UE_MESSAGE from S1AP
001446 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :0586   [0] INITIAL_UE_MESSAGE RCVD
mme_ue_s1ap_id  = 43
enb_ue_s1ap_id  = 70
001447 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :0594   [0] Sending NAS Establishment Indication to NAS for ue_id = 43
001448 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0172    EMMAS-SAP - Received primitive EMMAS_ESTABLISH_REQ (205)
001449 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0749    EMMAS-SAP - Received AS connection establish request
001450 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0810    EMMAS-SAP - Message Type = ATTACH_REQUEST(0x41) for (ue_id = 43)
001451 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_recv.c    :0189    EMMAS-SAP - Received Attach Request message for ue id 43
001452 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Attach.c          :0216    ATTACH REQ (ue_id = 43) (IMSI = 315010461196449)
001453 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Attach.c          :0233    EMM-PROC:  ATTACH - EPS attach type = IMSI (1)
001454 Wed Sep 06 16:31:39 2023 7FBE363F0700 WARNI MME-AP tasks/mme_app/mme_app_context.c :0347   [315010461196449]  No IMSI hashtable for this IMSI
001455 Wed Sep 06 16:31:39 2023 7FBE363F0700 NOTIC NAS-EM tasks/nas/emm/Attach.c          :0549    EMM-PROC  - Create EMM context ue_id = 43
001456 Wed Sep 06 16:31:39 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1109    Hit 3GPP TS 24_301R10_5_5_1_2_3__1 : EMM common procedure initiation during attach procedure
001457 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Authentication.c  :1478    Sending Authentication Information Request message to S6A for ue_id = 43
001458 Wed Sep 06 16:31:39 2023 7FBE31BE7700 INFO  S6A    common/common_utility_funs.cpp  :0054   [315010461196449] PLMN is not configured. Selecting default mode: SPGW_SUBSCRIBER
001459 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/nas_proc.c            :0368   [315010461196449] Received Authentication Information Answer from S6A for ue_id = 43
001460 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_cn.c      :1142    EMMCN-SAP - Received primitive EMM_CN_AUTHENTICATION_PARAM_RES (401)
001461 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0237    EMM-FSM   - Received event COMMON_PROC_ABORT (4) in state EMM-DEREGISTERED
001462 Wed Sep 06 16:31:39 2023 7FBE363F0700 WARNI NAS-EM tasks/nas/emm/sap/EmmDeregistere:0119    EMM-FSM state EMM_DEREGISTERED - Primitive _EMMREG_COMMON_PROC_ABORT is not valid
001463 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Authentication.c  :0166   [315010461196449] ue_id=43 EMM-PROC  - Initiate Authentication KSI = 0
001464 Wed Sep 06 16:31:39 2023 7FBE363F0700 WARNI NAS-EM tasks/nas/emm/LowerLayer.c      :0469    NO Valid Security Context Available
001465 Wed Sep 06 16:31:39 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Authentication.c  :1254    Hit 3GPP TS 24_301R10_5_4_2_2 : Authentication initiation by the network
001466 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0172    EMMAS-SAP - Received primitive EMMAS_SECURITY_REQ (201)
001467 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :1639    EMMAS-SAP - Send AS security request
001468 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_send.c    :1355    EMMAS-SAP - Send Authentication Request message for ue_id = 43
001469 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_context.c :0954   [315010461196449] UE STATE - CONNECTED.
001470 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0237    EMM-FSM   - Received event COMMON_PROC_REQ (1) in state EMM-DEREGISTERED
001471 Wed Sep 06 16:31:39 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0152    UE 43 EMM-FSM   - Status changed: EMM-DEREGISTERED ===> EMM-COMMON-PROCEDURE-INITIATED
001472 Wed Sep 06 16:31:39 2023 7FBE323E8700 NOTIC S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0588   [315010461196449] Send S1AP DOWNLINK_NAS_TRANSPORT message ue_id = 43 MME_UE_S1AP_ID = 43 eNB_UE_S1AP_ID = 70
001473 Wed Sep 06 16:31:40 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0324    Received S1AP UPLINK_NAS_TRANSPORT message MME_UE_S1AP_ID 43
001474 Wed Sep 06 16:31:40 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_itti_messagi:0077   [315010461196449] Sending NAS Uplink indication to NAS_MME_APP, mme_ue_s1ap_id = (43)
001475 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS    tasks/nas/nas_proc.c            :0308    Received NAS UPLINK DATA IND from S1AP for ue_id = 43
001476 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0172    EMMAS-SAP - Received primitive EMMAS_DATA_IND (214)
001477 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0623    EMMAS-SAP - Received AS data transfer indication (ue_id=43, delivered=true, length=11)
001478 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/sap/emm_as.c      :0402    Hit 3GPP TS 24_301R10_4_4_4_3__1 : Integrity checking of NAS signalling messages exception in the MME
001479 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/sap/emm_as.c      :0405    Hit 3GPP TS 24_301R10_4_4_4_3__2 : Process NAS signalling message in the MME, even if it fails the integrity check or MAC cannot be verified
001480 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_recv.c    :1007    EMMAS-SAP - Received Authentication Response message for ue id 43
001481 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Authentication.c  :0867   [315010461196449] EMM-PROC  - Authentication complete (ue_id=43)
001482 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Authentication.c  :0905    Hit 3GPP TS 24_301R10_5_4_2_4__1 : AUTHENTICATION RESPONSE received, stop T3460, check RES
001483 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Authentication.c  :0907    Hit 3GPP TS 24_301R10_5_4_2_4__2 : authentication procedure is success, new eKSI for new authentication procedure
001484 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0237    EMM-FSM   - Received event COMMON_PROC_CNF (2) in state EMM-COMMON-PROCEDURE-INITIATED
001485 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0152    UE 43 EMM-FSM   - Status changed: EMM-COMMON-PROCEDURE-INITIATED ===> EMM-DEREGISTERED
001486 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Attach.c          :1236   [315010461196449] ATTACH - Authentication procedure success!
001487 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1242    Hit 3GPP TS 24_301R10_5_5_1_2_3__1 : EMM common procedure initiation during attach procedure
001488 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1289    Hit 3GPP TS 24_301R10_5_5_1_2_3__1 : EMM common procedure initiation during attach procedure
001489 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/SecurityModeContro:0183   [315010461196449] EMM-PROC  - Initiate security mode control procedure, KSI = 0
001490 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/SecurityModeContro:0224    Hit 3GPP TS 24_301R10_5_4_3_2__2 : SMC initiation, reset DL NAS count, use SC
001491 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/SecurityModeContro:0842    Hit 3GPP TS 24_301R10_5_4_3_2__14 : SMC initiation, include replayed security capabilities, eKSI, algos
001492 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0172    EMMAS-SAP - Received primitive EMMAS_SECURITY_REQ (201)
001493 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :1639    EMMAS-SAP - Send AS security request
001494 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_send.c    :1469    EMMAS-SAP - Send Security Mode Command message for ue_id = 43
001495 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/SecurityModeContro:0889    Hit 3GPP TS 24_301R10_5_4_3_2__1 : SMC initiation, start T3460
001496 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0237    EMM-FSM   - Received event COMMON_PROC_REQ (1) in state EMM-DEREGISTERED
001498 Wed Sep 06 16:31:40 2023 7FBE323E8700 NOTIC S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0588   [315010461196449] Send S1AP DOWNLINK_NAS_TRANSPORT message ue_id = 43 MME_UE_S1AP_ID = 43 eNB_UE_S1AP_ID = 70
001497 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0152    UE 43 EMM-FSM   - Status changed: EMM-DEREGISTERED ===> EMM-COMMON-PROCEDURE-INITIATED
001499 Wed Sep 06 16:31:40 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0324    Received S1AP UPLINK_NAS_TRANSPORT message MME_UE_S1AP_ID 43
001500 Wed Sep 06 16:31:40 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_itti_messagi:0077   [315010461196449] Sending NAS Uplink indication to NAS_MME_APP, mme_ue_s1ap_id = (43)
001501 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS    tasks/nas/nas_proc.c            :0308    Received NAS UPLINK DATA IND from S1AP for ue_id = 43
001502 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0172    EMMAS-SAP - Received primitive EMMAS_DATA_IND (214)
001503 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0623    EMMAS-SAP - Received AS data transfer indication (ue_id=43, delivered=true, length=19)
001504 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/msg/emm_msg.c     :0179    EMM-MSG   - IMEISV: 9900168714035901
001505 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/sap/emm_as.c      :0424    Hit 3GPP TS 24_301R10_4_4_4_3__1 : Integrity checking of NAS signalling messages exception in the MME
001506 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_recv.c    :1124    EMMAS-SAP - Received Security Mode Complete message for ue id 43
001507 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/SecurityModeContro:0480   [315010461196449] EMM-PROC  - Security mode complete (ue_id=43)
001508 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/SecurityModeContro:0521    Hit 3GPP TS 24_301R10_5_4_3_4__1 : SMC completion, stop T3460,
001509 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/SecurityModeContro:0582    Hit 3GPP TS 24_301R10_5_4_3_4__2 : SMC completion, integ. cipher. all messages
001510 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0237    EMM-FSM   - Received event COMMON_PROC_CNF (2) in state EMM-COMMON-PROCEDURE-INITIATED
001511 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0152    UE 43 EMM-FSM   - Status changed: EMM-COMMON-PROCEDURE-INITIATED ===> EMM-DEREGISTERED
001512 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Attach.c          :1339   [315010461196449] ATTACH - Security procedure success!
001513 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Attach.c          :1438    ue_id=43 EMM-PROC  - Attach UE
001514 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/sap/esm_sap.c     :0139    ESM-SAP   - Received primitive ESM_UNITDATA_IND (20)
001515 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/sap/esm_recv.c    :0150   [315010461196449] ESM-SAP   - Received PDN Connectivity Request message (ue_id= 43, pti=3, ebi=0)
001516 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  SCTP   tasks/mme_app/mme_app_location.c:0067    Sending S6A UPDATE LOCATION REQ to S6A, ue_id =43
001517 Wed Sep 06 16:31:40 2023 7FBE31BE7700 INFO  S6A    common/common_utility_funs.cpp  :0054   [315010461196449] PLMN is not configured. Selecting default mode: SPGW_SUBSCRIBER
001518 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_main.c    :0233    Received S6A Update Location Answer from S6A
001519 Wed Sep 06 16:31:40 2023 7FBE363F0700 WARNI MME-AP tasks/mme_app/mme_app_location.c:0333    No MSISDN received for mme_app_handle_s6a_update_location_ans 315010461196449
001520 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/nas_proc.c            :0464    Received S6a-Update Location Answer Success for ue_id = 43
001521 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_cn.c      :1142    EMMCN-SAP - Received primitive EMM_CN_ULA_SUCCESS (403)
001522 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_apn_select:0135    Selected APN <internet>, PDN Type <0> for UE 315010461196449
001523 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/PdnConnectivity.c :0132    ESM-PROC  - PDN connectivity requested by the UE (ue_id=43)
001524 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/DefaultEpsBearerCo:0109   [315010461196449] ESM-PROC  - Default EPS bearer context activation (ue_id=43)
001525 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/esm_ebr_context.c :0094   [315010461196449] ESM-PROC  - Create new default EPS bearer context (ebi=5) for PDN connection (pid=0) for ue_id 43
001526 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP common/common_utility_funs.cpp  :0054   [315010461196449] PLMN is not configured. Selecting default mode: SPGW_SUBSCRIBER
001527 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_itti_messa:0443   [315010461196449] Sending s11 create session req message to SPGW task for ue_id 43
001528 Wed Sep 06 16:31:40 2023 7FBE333EA700 INFO  SPGW-A tasks/sgw/sgw_handlers.cpp      :0106   [315010461196449] Received S11 CREATE SESSION REQUEST from MME_APP
001529 Wed Sep 06 16:31:40 2023 7FBE333EA700 WARNI SPGW-A tasks/sgw/pgw_pco.cpp           :0444    PCO: Protocol/container identifier 0x0005 not supported now
001530 Wed Sep 06 16:31:40 2023 7FBE333EA700 WARNI SPGW-A tasks/sgw/pgw_pco.cpp           :0444    PCO: Protocol/container identifier 0x0011 not supported now
001531 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :1130   [315010461196449] Received S11_CREATE_SESSION_RESPONSE from S+P-GW for ue id 43 with MME S11 teid = 43, cause = 16
001532 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/nas_proc.c            :0481   [262157] Handle Create Session Response Success at NAS for ue_id = 43
001533 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_cn.c      :1142    EMMCN-SAP - Received primitive EMM_CN_CS_RESPONSE_SUCCESS (404)
001534 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/sap/esm_send.c    :0228    ESM-SAP   - Send Activate Default EPS Bearer Context Request message
001535 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/sap/esm_send.c    :0332    ESM-SAP   - Send Activate Default EPS Bearer Context Request message (pti=3, ebi=5)
001536 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/DefaultEpsBearerCo:0210   [315010461196449] ESM-PROC  - Initiate non standalone default EPS bearer context activation (ue_id=43, ebi=5)
001537 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/esm_ebr.c         :0521   [315010461196449] ESM-FSM   - Status of EPS bearer context 5 changed: BEARER CONTEXT INACTIVE ===> BEARER CONTEXT ACTIVE PENDING for ue id 43
001538 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1626    #NOT IMPLEMENTED 3GPP TS 24_301R10_5_5_1_2_4__3 : Attach accepted by the network, delete the stored UE radio capability information.
001539 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1629    Hit 3GPP TS 24_301R10_5_5_1_2_4__4 : Attach accepted by the network, store UE network capability IE or the MS network capability IE or both.
001540 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1636    Hit 3GPP TS 24_301R10_5_5_1_2_4__5 : Attach accepted by the network, use DRX parameter for the downlink transfer of signalling and user data
001541 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1641    Hit 3GPP TS 24_301R10_5_5_1_2_4__9 :
001542 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS    tasks/nas/emm/EmmCommon.c       :0572   [315010461196449] Matching partial list for originating TAI found! typeOfList=1
001543 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS    tasks/nas/emm/EmmCommon.c       :0658   [315010461196449]   Got GUTI 310.99 |0001|01|47e22f0b. The number of TAI partial lists: 1
001544 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1661    Hit 3GPP TS 24_301R10_5_5_1_2_4__6 :
001545 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1662    Hit 3GPP TS 24_301R10_5_5_1_2_4__10 :
001546 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1711    Hit 3GPP TS 24_301R10_5_5_1_2_4__14 :
001547 Wed Sep 06 16:31:40 2023 7FBE363F0700 NOTIC NAS    tasks/nas/emm/Attach.c          :1762    Hit 3GPP TS 24_301R10_5_5_1_2_4__2 :
001548 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :0172    EMMAS-SAP - Received primitive EMMAS_ESTABLISH_CNF (206)
001549 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_as.c      :2013    EMMAS-SAP - Send AS connection establish confirmation for (ue_id = 43)
001550 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_send.c    :0221    EMMAS-SAP - Send Attach Accept message, ue_id = 43
001551 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :0559   [315010461196449] MME APP : Sent Initial context Setup Request and Started guard timer for UE id 43 timer_id :2b
001552 Wed Sep 06 16:31:40 2023 7FBE323E8700 INFO  S1AP   tasks/s1ap/s1ap_mme_nas_procedur:0863    Received Connection Establishment Confirm from MME_APP for ue_id = 43
001553 Wed Sep 06 16:31:40 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_state_conv:0116    Looking for key 0x602000025bc0 with value 31099f00010147e22f0b strlen:20

Important lines:

001554 Wed Sep 06 16:31:40 2023 7FBE323E8700 NOTIC S1AP   tasks/s1ap/s1ap_mme_nas_procedur:1148   [315010461196449] Send S1AP_INITIAL_CONTEXT_SETUP_REQUEST message MME_UE_S1AP_ID = 43 eNB_UE_S1AP_ID = 70
001555 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :4228    Expired- Initial context setup response timer for ue_id 43
001556 Wed Sep 06 16:31:44 2023 7FBE363F0700 ERROR MME-AP tasks/mme_app/mme_app_bearer.c  :4608   [315010461196449] handle ics failure

Teardown

001557 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_cn.c      :1142    EMMCN-SAP - Received primitive EMMCN_IMPLICIT_DETACH_UE (407)
001558 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Detach.c          :0246    EMM-PROC  - SGS Detach type = NW-INITIATED-IMPLICIT-NONEPS (4) requested (ue_id=43)
001559 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/Detach.c          :0312    EMM-PROC  - Detach type = EPS (0) requested (ue_id=43)
001560 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  NAS-EM tasks/nas/emm/sap/emm_fsm.c     :0237    EMM-FSM   - Received event DETACH_REQ (9) in state EMM-DEREGISTERED
001561 Wed Sep 06 16:31:44 2023 7FBE363F0700 ERROR NAS-EM tasks/nas/emm/sap/EmmDeregistere:0195    EMM-FSM state EMM_DEREGISTERED - Primitive _EMMREG_DETACH_REQ is not valid
001562 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_detach.c  :0152    Handle Detach Req at MME app for ue-id: 43 with mme_s11_teid 43
001563 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_detach.c  :0067   [315010461196449] Handle Delete session request for mme_s11_teid :43
001564 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_detach.c  :0131   [315010461196449] Send delete session Req for teid to spgw task 43
001565 Wed Sep 06 16:31:44 2023 7FBE333EA700 INFO  SPGW-A tasks/sgw/sgw_handlers.cpp      :1059   [315010461196449] Handle delete session request for sgw_s11_teid 777502414
001566 Wed Sep 06 16:31:44 2023 7FBE333EA700 WARNI GTPv1- tasks/gtpv1-u/gtp_tunnel_openflo:0238    zero enb IP address not supported
001567 Wed Sep 06 16:31:44 2023 7FBE34BED700 ERROR GTPv1- lib/openflow/controller/PagingAp:0275    Not an IPv6 UE
001568 Wed Sep 06 16:31:44 2023 7FBE34BED700 INFO  GTPv1- lib/openflow/controller/PagingAp:0256    Deleted paging flow rule for UE IP 192.168.128.27
001569 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_bearer.c  :0899   [315010461196449] Received S11_DELETE_SESSION_RESPONSE from S+P-GW with teid 43, for ue id: 43, lbi: 5

001570 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_itti_messa:0087   [315010461196449] Sending UE Context Release Cmd to S1ap for (ue_id = 43)
UE Context Release Cause = (7)
001571 Wed Sep 06 16:31:44 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_state_conv:0116    Looking for key 0x602000025bc0 with value 31099f00010147e22f0b strlen:20
001572 Wed Sep 06 16:31:45 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_context.c :1147    Received UE context release complete message for ue_id: 43
001573 Wed Sep 06 16:31:45 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_purge_ue.c:0077    Sent PUR to S6a TASK for IMSI 315010461196449
001574 Wed Sep 06 16:31:45 2023 7FBE363F0700 INFO  MME-AP tasks/mme_app/mme_app_context.c :0116   [315010461196449] Deleted UE location from directoryd
001575 Wed Sep 06 16:31:45 2023 7FBE363F0700 INFO  NAS-ES tasks/nas/esm/sap/esm_sap.c     :0139    ESM-SAP   - Received primitive ESM_EPS_BEARER_CONTEXT_DEACTIVATE_REQ (10)
001576 Wed Sep 06 16:31:45 2023 7FBE363F0700 WARNI NAS-ES tasks/nas/esm/PdnConnectivity.c :0521    ESM-PROC  - PDN connection identifier is not valid
001577 Wed Sep 06 16:31:45 2023 7FBE363F0700 WARNI MME-AP tasks/mme_app/mme_app_context.c :0347   [315010461196449]  No IMSI hashtable for this IMSI

1 reply

aniket021997 Sep 15, 2023
Collaborator

Hi @FrankPetrilli,
Thanks for the pcap and mme log snap.
In pcap snap, it seems that the initial context setup response has been sent from the enb towards AGW.
But, at AGW - s1ap didn't send packet to mme. To verify this, will require S1AP debug logs (mme logs) to analyze further.
To reproduce the scenario, it will be great if we get the pcap to see what all Initial context setup response IEs involved in the pcap.

FrankPetrilli · 2023-09-19T21:10:24Z

FrankPetrilli
Sep 19, 2023
Author

Hey all,

Oddly enough, in spite of setting reduced MTUs, etc, this was resolved by removing the IPSec tunnel from the picture and putting the two directly adjacent in layer-3 space. Something to be looked at so the IPSec transport use case can be looked into for the future, but for now I'll close this issue.

0 replies

aniket021997 · 2023-09-22T10:06:26Z

aniket021997
Sep 22, 2023
Collaborator

Hi @FrankPetrilli , we are able to establish PDU session over IPsec tunnel. Please find attached snaps and Pcap for reference.

mme_logs.zip

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"Received a termination request from Access" 5 seconds after connect #15298

{{title}}

Replies: 5 comments 1 reply

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

"Received a termination request from Access" 5 seconds after connect #15298

FrankPetrilli Aug 30, 2023

Setup

What's happening

Logs

Packet Capture

Replies: 5 comments · 1 reply

prabinakpattnaik Aug 31, 2023 Maintainer

panyogesh Sep 1, 2023 Maintainer

FrankPetrilli Sep 6, 2023 Author

Normal setup

Important lines:

Teardown

aniket021997 Sep 15, 2023 Collaborator

FrankPetrilli Sep 19, 2023 Author

aniket021997 Sep 22, 2023 Collaborator

FrankPetrilli
Aug 30, 2023

Replies: 5 comments 1 reply

prabinakpattnaik
Aug 31, 2023
Maintainer

panyogesh
Sep 1, 2023
Maintainer

FrankPetrilli
Sep 6, 2023
Author

aniket021997 Sep 15, 2023
Collaborator

FrankPetrilli
Sep 19, 2023
Author

aniket021997
Sep 22, 2023
Collaborator