[srslte-users] UE is not ECM connected

Tue Apr 20 12:49:03 UTC 2021

Hi All.
I have bladerf. I start srslte everything works until the session is interrupted. This may be due to the inactivity of the subscriber.
New session does not open.

12:26:46.086915 [GTPU] [D] Forwarded packet to TUN interface. Bytes= 60/60
12:26:46.245960 [SPGW] [D] Message received at SPGW: S1-U Message
12:26:46.245978 [GTPU] [D] Received PDU from S1-U. Bytes=60
12:26:46.245982 [GTPU] [D] TEID 0x1. Bytes=60
12:26:46.246016 [GTPU] [D] Forwarded packet to TUN interface. Bytes= 60/60
12:27:11.587007 [S1AP] [I] Received S1AP msg. Size: 25
12:27:11.587038 [S1AP] [I] Received Initiating PDU
12:27:11.587043 [S1AP] [I] Received UE Context Release Request Message.
12:27:11.587046 [S1AP] [I] Received UE Context Release Request. MME-UE S1AP Id: 1
12:27:11.587064 [S1AP] [I] There are active E-RABs, send release access bearers request
12:27:11.587068 [MME GTPC] [I] Sending GTP-C Release Access Bearers Request
12:27:11.587069 [MME GTPC] [I] GTP-C Release Access Berarers Request -- S-GW Control TEID 1
12:27:11.587070 [MME GTPC] [D] Sending S-11 GTP-C PDU
12:27:11.587085 [MME GTPC] [D] MME S11 Sent 1360 Bytes.
12:27:11.587100 [SPGW] [D] Message received at SPGW: S11 Message
12:27:11.587128 [SPGW GTPC] [D] Received GTP-C PDU. Message type: GTPC_MSG_TYPE_RELEASE_ACCESS_BEARERS_REQUEST
12:27:11.685533 [S1AP] [D] Transmitting S1AP PDU. eNB SCTP association Id: 4
12:27:11.685640 [S1AP] [D] Waiting for S1-MME or S11 Message
12:27:11.685751 [S1AP] [I] Received S1AP msg. Size: 19
12:27:11.685774 [S1AP] [I] Received Succeseful Outcome PDU
12:27:11.685776 [S1AP] [I] Received UE Context Release Complete
12:27:11.685780 [S1AP] [I] Received UE Context Release Complete. MME-UE S1AP Id: 1
12:27:11.685804 [S1AP] [I] Released UE ECM Context.
12:27:11.685806 [S1AP] [I] UE Context Release Completed.
12:27:11.685814 [S1AP] [D] Waiting for S1-MME or S11 Message
12:27:29.595848 [S1AP] [I] Received S1AP msg. Size: 59
12:27:29.595898 [S1AP] [I] Received Initiating PDU
12:27:29.595903 [S1AP] [I] Received Initial UE Message.
12:27:29.595926 [S1AP] [I] Initial UE message: NAS Message Type Unknown
12:27:29.595936 [S1AP] [I] Received Initial UE message -- Service Request
12:27:29.595938 [NAS ] [I] Service request -- S-TMSI 0x15f615a7
12:27:29.595947 [NAS ] [I] Service request -- eNB UE S1AP Id 2
12:27:29.595951 [S1AP] [D] Found IMSI 901700000000001 from M-TMSI 0x15f615a7
12:27:29.596124 [NAS ] [W] Short integrity check failure. Local: count=22, [24 03 e8 06], Received: count=23, [82 3c]
12:27:29.596127 [NAS ] [I] Service Request -- Short MAC invalid
12:27:29.596129 [S1AP] [D] Saved UE context corresponding to MME UE S1AP Id 2
12:27:29.596130 [S1AP] [D] Added UE with MME-UE S1AP Id 2 to eNB with association 4
12:27:29.596132 [S1AP] [D] Sending message to eNB with SCTP association 4. MME UE S1AP ID 2, eNB UE S1AP ID 2
12:27:29.596135 [S1AP] [D] Transmitting S1AP PDU. eNB SCTP association Id: 4
12:27:29.596171 [NAS ] [W] Service Request -- Short MAC invalid. Sending service reject.
12:27:29.596172 [NAS ] [I] Service Reject -- eNB_UE_S1AP_ID 2 MME_UE_S1AP_ID 2.
12:27:29.596175 [S1AP] [D] Waiting for S1-MME or S11 Message
12:27:33.750444 [SPGW] [D] Message received at SPGW: SGi Message
12:27:33.750479 [GTPU] [D] Received SGi PDU. Bytes 48
12:27:33.750482 [GTPU] [W] IPv6 not supported yet.
12:27:39.737784 [S1AP] [I] Received S1AP msg. Size: 154
12:27:39.737836 [S1AP] [I] Received Initiating PDU
12:27:39.737840 [S1AP] [I] Received Initial UE Message.
12:27:39.737867 [S1AP] [I] Initial UE message: LIBLTE_MME_MSG_TYPE_ATTACH_REQUEST
12:27:39.737875 [S1AP] [I] Received Initial UE message -- Attach Request
12:27:39.737891 [NAS ] [I] Attach request -- IMSI: 901700000000001
12:27:39.737896 [NAS ] [I] Attach request -- eNB-UE S1AP Id: 3
12:27:39.737902 [NAS ] [I] Attach request -- Attach type: 2
12:27:39.737909 [NAS ] [I] Attach Request -- UE Network Capabilities EEA: 11110000
12:27:39.737914 [NAS ] [I] Attach Request -- UE Network Capabilities EIA: 01110000
12:27:39.737919 [NAS ] [I] Attach Request -- MS Network Capabilities Present: true
12:27:39.737925 [NAS ] [I] PDN Connectivity Request -- EPS Bearer Identity requested: 0
12:27:39.737930 [NAS ] [I] PDN Connectivity Request -- Procedure Transaction Id: 173
12:27:39.737935 [NAS ] [I] PDN Connectivity Request -- ESM Information Transfer requested: true
12:27:39.737939 [NAS ] [I] Attach Request -- Found previously attached UE.
12:27:39.737943 [MME GTPC] [I] Sending GTP-C Delete Session Request request. IMSI 0
12:27:39.737946 [MME GTPC] [E] Could not find GTP-C context to remove
12:27:39.737948 [S1AP] [E] UE is not ECM connected. No send context release command. MME UE S1AP Id 2
12:27:39.737950 [S1AP] [I] Cannot delete UE context, UE not found. IMSI: 0
12:27:39.737967 [NAS ] [D] NAS Context Initialized. MCC: 0xf001, MNC 0xff01
12:27:39.737971 [HSS ] [D] Generating AUTH info answer
12:27:39.737984 [HSS ] [D] User Key : 
             0000: 00 11 22 33 44 55 66 77 88 99 aa bb cc dd ee ff 
12:27:39.737988 [HSS ] [D] User OPc : 
             0000: 63 bf a5 0e e6 52 33 65 ff 14 c1 f4 5f 88 73 7d 
12:27:39.737992 [HSS ] [D] User Rand : 
             0000: 7c e7 c6 b5 4f e8 72 68 f6 90 33 85 e0 86 2c 65 
12:27:39.737994 [HSS ] [D] User XRES: 
             0000: 01 31 d8 2e 77 a6 86 51 
12:27:39.737997 [HSS ] [D] User CK: 
             0000: ff 0b 37 61 a3 6f 42 bc 8e 2c 3a ec 28 54 bc 45 
12:27:39.738000 [HSS ] [D] User IK: 
             0000: 69 8f 2b 99 60 ae e5 df c2 92 9a 28 4e a6 15 4a 
12:27:39.738004 [HSS ] [D] User AK: 
             0000: 99 9f e4 67 64 cd 
12:27:39.738008 [HSS ] [D] User SQN : 
             0000: 00 00 00 00 21 0f 
12:27:39.738011 [HSS ] [D] User MAC : 
             0000: ba 48 33 66 40 c1 1e 4c 
12:27:39.738019 [HSS ] [D] User MCC : f001  MNC : ff01 
12:27:39.738024 [HSS ] [D] User k_asme : 
             0000: 69 a7 78 28 4b 95 d7 2d 7e 65 07 1e 93 0f aa 70 
             0010: d1 ee 45 a9 1d ba 86 36 06 5a 0a 86 6e 3e 2f 0f 
12:27:39.738027 [HSS ] [D] User AUTN: 
             0000: 99 9f e4 67 45 c2 90 01 ba 48 33 66 40 c1 1e 4c 
12:27:39.738028 [HSS ] [D] Incremented SQN  -- IMSI: 901700000000001
12:27:39.738032 [HSS ] [D] SQN: 
             0000: 00 00 00 00 21 30 
12:27:39.738034 [S1AP] [E] UE Context already exists. IMSI 901700000000001
12:27:39.738039 [S1AP] [D] Saved UE context corresponding to MME UE S1AP Id 3
12:27:39.738040 [S1AP] [D] Added UE with MME-UE S1AP Id 3 to eNB with association 4
12:27:39.738041 [NAS ] [I] Packing Authentication Request
12:27:39.738050 [S1AP] [D] Sending message to eNB with SCTP association 4. MME UE S1AP ID 3, eNB UE S1AP ID 3
12:27:39.738054 [S1AP] [D] Transmitting S1AP PDU. eNB SCTP association Id: 4
12:27:39.738107 [NAS ] [I] Downlink NAS: Sending Authentication Request
12:27:39.738114 [S1AP] [D] Waiting for S1-MME or S11 Message
12:27:39.890120 [S1AP] [I] Received S1AP msg. Size: 57
12:27:39.890182 [S1AP] [I] Received Initiating PDU
12:27:39.890186 [S1AP] [I] Received Uplink NAS Transport Message.
12:27:39.890191 [S1AP] [D] Received uplink NAS and found UE NAS context. MME-UE S1AP id: 3
12:27:39.890195 [S1AP] [I] UL NAS: sec_hdr_type: LIBLTE_MME_SECURITY_HDR_TYPE_PLAIN_NAS, mac_vaild: no, msg_encrypted: no
12:27:39.890196 [S1AP] [I] UL NAS: Received Authentication Response
12:27:39.890218 [NAS ] [I] Authentication Response -- IMSI 901700000000001
12:27:39.890234 [NAS ] [I] Authentication response -- RES
             0000: 01 31 d8 2e 77 a6 86 51 
12:27:39.890237 [NAS ] [I] Authentication response -- XRES
             0000: 01 31 d8 2e 77 a6 86 51 
12:27:39.890241 [NAS ] [I] UE Authentication Accepted.
12:27:39.890243 [NAS ] [I] Packing Security Mode Command
12:27:39.890256 [NAS ] [I] Key NAS Encryption (k_nas_enc)
             0000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
             0010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
12:27:39.890262 [NAS ] [I] Key NAS Integrity (k_nas_int)
             0000: 3e 06 32 8e 9a 55 17 32 aa 61 47 47 5a 98 17 88 
             0010: 35 c7 b5 bd 77 a5 20 78 d9 a9 ca b2 e2 37 e2 23 
12:27:39.890265 [NAS ] [I] Generating KeNB with UL NAS COUNT: 0
12:27:39.890269 [NAS ] [I] Key eNodeB (k_enb)
             0000: 96 d0 e6 48 84 65 e9 1a 0e 78 14 4d b2 90 eb 84 
             0010: ae 32 2d 87 84 b1 90 28 9c 4c 2c c1 2d b1 88 c1 
12:27:39.890453 [NAS ] [D] Generating MAC with inputs: Algorithm 128-EIA1, DL COUNT 0
12:27:39.890459 [S1AP] [D] Sending message to eNB with SCTP association 4. MME UE S1AP ID 3, eNB UE S1AP ID 3
12:27:39.890465 [S1AP] [D] Transmitting S1AP PDU. eNB SCTP association Id: 4
12:27:39.890498 [S1AP] [D] Waiting for S1-MME or S11 Message
12:27:39.909500 [S1AP] [I] Received S1AP msg. Size: 54
12:27:39.909563 [S1AP] [I] Received Initiating PDU
12:27:39.909569 [S1AP] [I] Received Uplink NAS Transport Message.
12:27:39.909575 [S1AP] [D] Received uplink NAS and found UE NAS context. MME-UE S1AP id: 3
12:27:39.909750 [NAS ] [I] Integrity check ok. Local: count=0, Received: count=0
12:27:39.909761 [S1AP] [D] Encrypted
             0000: 47 ca 38 f2 7f 00 07 5e 
12:27:39.909765 [S1AP] [D] Decrypted
             0000: 47 ca 38 f2 7f 00 07 5e 
12:27:39.909768 [S1AP] [I] UL NAS: sec_hdr_type: LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED_WITH_NEW_EPS_SECURITY_CONTEXT, mac_vaild: yes, msg_encrypted: yes
12:27:39.909769 [S1AP] [I] UL NAS: Received Security Mode Complete
12:27:39.909782 [NAS ] [I] Security Mode Command Complete -- IMSI: 901700000000001
12:27:39.909788 [NAS ] [I] Sending ESM information request
12:27:39.909791 [NAS ] [I] Packing ESM Information request
12:27:39.909956 [NAS ] [D] Generating MAC with inputs: Algorithm 128-EIA1, DL COUNT 1
12:27:39.909970 [S1AP] [D] Sending message to eNB with SCTP association 4. MME UE S1AP ID 3, eNB UE S1AP ID 3
12:27:39.909974 [S1AP] [D] Transmitting S1AP PDU. eNB SCTP association Id: 4
12:27:39.910007 [S1AP] [D] Waiting for S1-MME or S11 Message
12:27:39.929938 [S1AP] [I] Received S1AP msg. Size: 64
12:27:39.930001 [S1AP] [I] Received Initiating PDU
12:27:39.930007 [S1AP] [I] Received Uplink NAS Transport Message.
12:27:39.930012 [S1AP] [D] Received uplink NAS and found UE NAS context. MME-UE S1AP id: 3
12:27:39.930193 [NAS ] [I] Integrity check ok. Local: count=1, Received: count=1
12:27:39.930205 [S1AP] [D] Encrypted
             0000: 27 b2 6f 6d ad 01 02 ad da 28 07 06 73 72 73 61 
             0010: 70 6e 
12:27:39.930209 [S1AP] [D] Decrypted
             0000: 27 b2 6f 6d ad 01 02 ad da 28 07 06 73 72 73 61 
             0010: 70 6e 
12:27:39.930212 [S1AP] [I] UL NAS: sec_hdr_type: LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED, mac_vaild: yes, msg_encrypted: yes
12:27:39.930213 [S1AP] [I] UL NAS: Received ESM Information Response
12:27:39.930228 [NAS ] [I] ESM Info: EPS bearer id 0

--
Андрей Попов
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.srsran.com/pipermail/srsran-users/attachments/20210420/d6944afb/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: log.zip
Type: application/zip
Size: 123947 bytes
Desc: not available
URL: <https://lists.srsran.com/pipermail/srsran-users/attachments/20210420/d6944afb/attachment.zip>