Hi Lin,
On Tue, Jun 06, 2017 at 06:09:16PM +0800, Lin HUANG wrote:
In the output of HLR, it seems the authentication is OK:
20170606183004032 DAUC <0003> db_auc.c:222 901700000014922: Generated 5 vectors 20170606183004032 DAUC <0003> db_auc.c:227 901700000014922: Updating SQN=1728 in DB ... 20170606183005665 DMAIN <0000> luop.c:148 LU OP state change: NULL -> LU RECEIVED 20170606183005665 DMAIN <0000> luop.c:148 LU OP state change: LU RECEIVED
-> ISD SENT
looks good
But in the output of MSC:
20170606183005665 DMM <0002> gsm_04_08.c:3798 <- SECURITY MODE COMPLETE IMSI:901700000014922 ... 20170606183005666 DMM <0002> gsm_04_08.c:201 -> MSISDN:333 LOCATION UPDATE ACCEPT ... 20170606183005666 DMSC <000a> msc_ifaces.c:44 msc_tx 17 bytes to MSISDN:333 via RAN_UTRAN_IU 20170606183005666 DRANAP <001a> iu.c:391 Transmitting L3 Message as RANAP DT (SUA link 0xcacde0 conn_id 0) 20170606183005666 DSUA <001b> sua.c:506 Received SCCP User Primitive (N-DATArequest) 20170606183005666 DSUA <001b> sua.c:160 sua_link_send(01 00 08 08 00 00 00 40 00 06 00 08 00 00 00 00 01 05 00 08 00 00 03 e8 01 0b 00 26 00 14 00 1e 00 00 02 00 10 40 12 11 05 02 09 f1 89 28 b6 17 08 99 10 07 00 00 10 94 22 00 3b 40 01 00 00 00 ) 20170606183005666 DVLR <001d> vlr_lu_fsm.c:321 lu_compl_vlr_fsm(901700000014922)[0xcab580]{LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE 20170606183005666 DVLR <001d> vlr_lu_fsm.c:355 vlr_lu_fsm(901700000014922)[0xcd5250]{VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
^ Location updating is successful at this point. The Finite State Machine for LU is hence torn down:
20170606183005666 DVLR <001d> vlr_lu_fsm.c:733 lu_compl_vlr_fsm(901700000014922)[0xcab580]{LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) 20170606183005666 DVLR <001d> vlr_lu_fsm.c:733 lu_compl_vlr_fsm(901700000014922)[0xcab580]{LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000014922)[0xcd5250] 20170606183005666 DVLR <001d> vlr_lu_fsm.c:733 lu_compl_vlr_fsm(901700000014922)[0xcab580]{LU_COMPL_VLR_S_DONE}: Freeing instance 20170606183005666 DVLR <001d> fsm.c:275 lu_compl_vlr_fsm(901700000014922)[0xcab580]{LU_COMPL_VLR_S_DONE}: Deallocated 20170606183005666 DVLR <001d> vlr_lu_fsm.c:700 vlr_lu_fsm(901700000014922)[0xcd5250]{VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE 20170606183005666 DMM <0002> vlr_lu_fsm.c:692 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED 20170606183005666 DMM <0002> subscr_conn.c:77 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU 20170606183005666 DMM <0002> subscr_conn.c:84 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
The connection to the phone is now classified as valid and usable.
20170606183005668 DMM <0002> subscr_conn.co:132 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Why is there a 'Received Event SUBSCR_CONN_E_BUMP'?
A "bump" event triggers a query whether any jobs are still pending for a connection, like delivering an SMS or somesuch. Typically after a LU there is nothing left to do. The phone is attached but idle:
20170606183005668 DMM <0002> subscr_conn.c:168 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn 20170606183005668 DMM <0002> subscr_conn.c:169 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED 20170606183005668 DMM <0002> subscr_conn.c:255 Subscr_Conn(901700000014922)[0xcd22f0]{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Indeed nothing left to do, connection is discarded, phone is subscribed and waiting for any events that would create a new connection.
So everything looks good from these logs. Cannot tell why this procedure would repeat over and over? Does it?
~N