Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 10c641979813c3bd2a66a7fd95f656731b83c1f8 / . / tests / msc_vlr / msc_vlr_test_reject_concurrency.err
blob: 8221e78531c8e7d781764f1410915853dd7b4824 [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2talloc_total_blocks(tall_bsc_ctx) == 12
3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]4===== test_reject_2nd_conn
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]5- Location Update Request on one connection
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]6 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]7 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]8DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]9DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]10DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]11DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]12DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]13DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]14DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
15DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
16DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
17DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]18DREF VLR subscr unknown usage increases to: 1
19DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
20DVLR New subscr, IMSI: 901700000004620
21DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]22DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]23DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
24DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
25DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
26DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
27DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
28DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
29DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
30DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]31DVLR GSUP tx: 04010809710000004026f0
32GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]33DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
34DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
35DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]36DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]37DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
38DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]39 lu_result_sent == 0
40 llist_count(&net->subscr_conns) == 1
41- Another Location Update Request from the same subscriber on another connection is rejected
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]42 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]43 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]44DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]45DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]46DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]47DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]48DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]49DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]50DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
51DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
52DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
53DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]54DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]55DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: A Location Updating process is already pending for this subscriber. Aborting.
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]56- sending LU Reject for unknown, cause 22
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]57DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_DONE
58DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
59DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]60DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]61- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]62DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
63DRR 901700000004620: internal error during Location Updating attempt
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]64DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]65 bssap_clear_sent == 1
66 lu_result_sent == 2
67- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]68DREF unknown: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]69DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
70DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
71DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
72DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
73DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
74DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
75DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
76DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]77DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]78DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
79DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]80 llist_count(&net->subscr_conns) == 1
81---
82- The first connection can still complete its LU
83- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
84<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
85DVLR GSUP rx 17: 10010809710000004026f00804036470f1
86DREF VLR subscr IMSI:901700000004620 usage increases to: 2
87DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]88DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]89DVLR GSUP tx: 12010809710000004026f0
90GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
91DREF VLR subscr MSISDN:46071 usage decreases to: 1
92<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
93 lu_result_sent == 0
94- HLR also sends GSUP _UPDATE_LOCATION_RESULT
95<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
96DVLR GSUP rx 11: 06010809710000004026f0
97DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]98DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
99DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
100DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
101DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
102DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
103DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
104DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
105DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
106DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
107DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
108DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
109DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
110DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
111DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
112DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
113DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
114DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
115DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
116DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
117DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
118DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
119DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]120- sending LU Accept for MSISDN:46071
121DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]122DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
123DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
124DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
125DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
126DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
127DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
128DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
129DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
130DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
131DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
132DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]133DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]134DREF VLR subscr MSISDN:46071 usage increases to: 4
135DREF VLR subscr MSISDN:46071 usage decreases to: 3
136- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]137DREF VLR subscr MSISDN:46071 usage decreases to: 2
138<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
139 bssap_clear_sent == 1
140- LU was successful, and the conn has already been closed
141 lu_result_sent == 1
142- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]143DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]144DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
145DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
146DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
147DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
148DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
149DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
150DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
151DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]152DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]153DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]154DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
155DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]156 llist_count(&net->subscr_conns) == 0
157DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]158===== test_reject_2nd_conn: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]159
160full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]161talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]162
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]163===== test_reject_lu_during_lu
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]164- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]165 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]166 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]167DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]168DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]169DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]170DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]171DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]172DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]173DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
174DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
175DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
176DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]177DREF VLR subscr unknown usage increases to: 1
178DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
179DVLR New subscr, IMSI: 901700000004620
180DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]181DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]182DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
183DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
184DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
185DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
186DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
187DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
188DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
189DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]190DVLR GSUP tx: 04010809710000004026f0
191GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]192DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
193DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
194DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]195DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]196DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
197DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]198 lu_result_sent == 0
199 llist_count(&net->subscr_conns) == 1
200---
201- Another Location Update Request from the same subscriber on the same conn is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]202 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]203DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]204DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]205DMM Cannot accept another LU, conn already busy establishing authenticity; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]206DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]207DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
208DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]209 lu_result_sent == 0
210 llist_count(&net->subscr_conns) == 1
211---
212- The first LU can still complete
213- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
214<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
215DVLR GSUP rx 17: 10010809710000004026f00804036470f1
216DREF VLR subscr IMSI:901700000004620 usage increases to: 2
217DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]218DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]219DVLR GSUP tx: 12010809710000004026f0
220GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
221DREF VLR subscr MSISDN:46071 usage decreases to: 1
222<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
223 lu_result_sent == 0
224- HLR also sends GSUP _UPDATE_LOCATION_RESULT
225<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
226DVLR GSUP rx 11: 06010809710000004026f0
227DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]228DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
229DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
230DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
231DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
232DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
233DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
234DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
235DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
236DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
237DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
238DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
239DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
240DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
241DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
242DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
243DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
244DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
245DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
246DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
247DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
248DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
249DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]250- sending LU Accept for MSISDN:46071
251DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]252DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
253DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
254DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
255DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
256DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
257DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
258DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
259DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
260DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
261DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
262DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]263DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]264DREF VLR subscr MSISDN:46071 usage increases to: 4
265DREF VLR subscr MSISDN:46071 usage decreases to: 3
266- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]267DREF VLR subscr MSISDN:46071 usage decreases to: 2
268<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
269 bssap_clear_sent == 1
270- LU was successful, and the conn has already been closed
271 lu_result_sent == 1
272- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]273DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]274DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
275DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
276DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
277DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
278DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
279DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
280DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
281DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]282DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]283DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]284DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
285DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]286 llist_count(&net->subscr_conns) == 0
287DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]288===== test_reject_lu_during_lu: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]289
290full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]291talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]292
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]293===== test_reject_cm_during_lu
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]294- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]295 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]296 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]297DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]298DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]299DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]300DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]301DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]302DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]303DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
304DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
305DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
306DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]307DREF VLR subscr unknown usage increases to: 1
308DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
309DVLR New subscr, IMSI: 901700000004620
310DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]311DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]312DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
313DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
314DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
315DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
316DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
317DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
318DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
319DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]320DVLR GSUP tx: 04010809710000004026f0
321GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]322DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
323DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
324DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]325DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]326DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
327DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]328 lu_result_sent == 0
329 llist_count(&net->subscr_conns) == 1
330---
331- A CM Service Request in the middle of a LU is rejected
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]332 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]333DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]334DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]335DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]336DMM Cannot accept CM Service Request, conn already busy establishing authenticity
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]337DMM -> CM SERVICE Reject cause: 22
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]338DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]339- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_CM_SERV_REJ: 052216
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]340- DTAP matches expected message
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]341DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]342DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
343DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]344 lu_result_sent == 0
345 cm_service_result_sent == 0
Neels Hofmeyr9fe52e42018-04-02 22:46:55 +0200[diff] [blame]346 dtap_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]347 llist_count(&net->subscr_conns) == 1
348---
349- The first LU can still complete
350- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
351<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
352DVLR GSUP rx 17: 10010809710000004026f00804036470f1
353DREF VLR subscr IMSI:901700000004620 usage increases to: 2
354DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]355DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]356DVLR GSUP tx: 12010809710000004026f0
357GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
358DREF VLR subscr MSISDN:46071 usage decreases to: 1
359<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
360 lu_result_sent == 0
361- HLR also sends GSUP _UPDATE_LOCATION_RESULT
362<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
363DVLR GSUP rx 11: 06010809710000004026f0
364DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]365DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
366DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
367DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
368DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
369DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
370DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
371DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
372DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
373DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
374DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
375DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
376DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
377DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
378DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
379DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
380DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
381DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
382DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
383DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
384DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
385DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
386DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]387- sending LU Accept for MSISDN:46071
388DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]389DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
390DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
391DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
392DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
393DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
394DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
395DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
396DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
397DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
398DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
399DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]400DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]401DREF VLR subscr MSISDN:46071 usage increases to: 4
402DREF VLR subscr MSISDN:46071 usage decreases to: 3
403- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]404DREF VLR subscr MSISDN:46071 usage decreases to: 2
405<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
406 bssap_clear_sent == 1
407- LU was successful, and the conn has already been closed
408 lu_result_sent == 1
409- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]410DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]411DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
412DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
413DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
414DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
415DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
416DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
417DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
418DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]419DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]420DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]421DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
422DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]423 llist_count(&net->subscr_conns) == 0
424DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]425===== test_reject_cm_during_lu: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]426
427full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]428talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]429
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]430===== test_reject_paging_resp_during_lu
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]431- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]432 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]433 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]434DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]435DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]436DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]437DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]438DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]439DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]440DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
441DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
442DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
443DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]444DREF VLR subscr unknown usage increases to: 1
445DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
446DVLR New subscr, IMSI: 901700000004620
447DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]448DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]449DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
450DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
451DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
452DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
453DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
454DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
455DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
456DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]457DVLR GSUP tx: 04010809710000004026f0
458GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]459DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
460DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
461DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]462DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]463DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
464DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]465 lu_result_sent == 0
466 llist_count(&net->subscr_conns) == 1
467---
468- An erratic Paging Response is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]469 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]470DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]471DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]472DMM Ignoring Paging Response, conn already busy establishing authenticity
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]473DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]474DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
475DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]476 lu_result_sent == 0
477 llist_count(&net->subscr_conns) == 1
478---
479- The first LU can still complete
480- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
481<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
482DVLR GSUP rx 17: 10010809710000004026f00804036470f1
483DREF VLR subscr IMSI:901700000004620 usage increases to: 2
484DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]485DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]486DVLR GSUP tx: 12010809710000004026f0
487GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
488DREF VLR subscr MSISDN:46071 usage decreases to: 1
489<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
490 lu_result_sent == 0
491- HLR also sends GSUP _UPDATE_LOCATION_RESULT
492<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
493DVLR GSUP rx 11: 06010809710000004026f0
494DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]495DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
496DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
497DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
498DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
499DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
500DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
501DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
502DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
503DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
504DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
505DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
506DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
507DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
508DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
509DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
510DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
511DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
512DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
513DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
514DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
515DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
516DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]517- sending LU Accept for MSISDN:46071
518DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]519DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
520DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
521DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
522DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
523DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
524DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
525DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
526DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
527DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
528DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
529DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]530DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]531DREF VLR subscr MSISDN:46071 usage increases to: 4
532DREF VLR subscr MSISDN:46071 usage decreases to: 3
533- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]534DREF VLR subscr MSISDN:46071 usage decreases to: 2
535<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
536 bssap_clear_sent == 1
537- LU was successful, and the conn has already been closed
538 lu_result_sent == 1
539- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]540DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]541DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
542DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
543DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
544DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
545DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
546DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
547DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
548DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]549DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]550DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]551DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
552DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]553 llist_count(&net->subscr_conns) == 0
554DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]555===== test_reject_paging_resp_during_lu: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]556
557full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]558talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]559
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]560===== test_reject_lu_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]561---
562- Subscriber does a normal LU
563- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]564 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]565 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]566DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]567DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]568DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]569DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]570DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]571DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]572DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
573DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
574DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
575DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]576DREF VLR subscr unknown usage increases to: 1
577DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
578DVLR New subscr, IMSI: 901700000004620
579DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]580DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]581DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
582DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
583DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
584DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
585DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
586DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
587DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
588DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]589DVLR GSUP tx: 04010809710000004026f0
590GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]591DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
592DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
593DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]594DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]595DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
596DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]597 lu_result_sent == 0
598 llist_count(&net->subscr_conns) == 1
599- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
600<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
601DVLR GSUP rx 17: 10010809710000004026f00804036470f1
602DREF VLR subscr IMSI:901700000004620 usage increases to: 2
603DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]604DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]605DVLR GSUP tx: 12010809710000004026f0
606GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
607DREF VLR subscr MSISDN:46071 usage decreases to: 1
608<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
609 lu_result_sent == 0
610- HLR also sends GSUP _UPDATE_LOCATION_RESULT
611<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
612DVLR GSUP rx 11: 06010809710000004026f0
613DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]614DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
615DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
616DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
617DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
618DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
619DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
620DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
621DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
622DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
623DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
624DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
625DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
626DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
627DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
628DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
629DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
630DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
631DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
632DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
633DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
634DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
635DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]636- sending LU Accept for MSISDN:46071
637DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]638DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
639DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
640DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
641DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
642DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
643DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
644DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
645DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
646DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
647DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
648DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]649DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]650DREF VLR subscr MSISDN:46071 usage increases to: 4
651DREF VLR subscr MSISDN:46071 usage decreases to: 3
652- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]653DREF VLR subscr MSISDN:46071 usage decreases to: 2
654<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
655 bssap_clear_sent == 1
656- LU was successful, and the conn has already been closed
657 lu_result_sent == 1
658- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]659DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]660DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
661DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
662DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
663DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
664DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
665DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
666DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
667DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]668DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]669DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]670DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
671DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]672 llist_count(&net->subscr_conns) == 0
673---
674- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]675 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]676 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]677DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]678DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]679DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]680DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]681DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
682DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
683DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
684DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
685DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]686DREF VLR subscr MSISDN:46071 usage increases to: 2
687DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]688DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
689DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
690DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
691DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
692DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
693DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
694DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]695DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]696DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]697DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]698- sending CM Service Accept for MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]699DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]700DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9: compl_l3,cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]701DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
702DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]703DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]704DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
705DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]706DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]707 cm_service_result_sent == 1
708msc_subscr_conn_is_accepted() == true
709- A LU request on an open conn is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]710 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]711DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]712DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]713DMM Cannot accept another LU, conn already established; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]714DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]715 lu_result_sent == 0
716 llist_count(&net->subscr_conns) == 1
717---
718- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]719 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]720DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]721DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]722DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
723DREF VLR subscr MSISDN:46071 usage increases to: 3
724DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]725DREF VLR subscr MSISDN:46071 usage increases to: 4
726DREF VLR subscr MSISDN:46071 usage decreases to: 3
727DREF VLR subscr MSISDN:46071 usage decreases to: 2
728DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]729DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE
730DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]731DREF MSISDN:46071: MSC conn use + release == 3 (0x10a: dtap,cm_service,release)
732DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102: dtap,release)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]733DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]734DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]735- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]736DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]737 bssap_clear_sent == 1
738- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]739DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]740DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
741DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
742DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]743DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
744DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
745DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
746DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]747DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]748DREF VLR subscr MSISDN:46071 usage decreases to: 0
749DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]750DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
751DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]752 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]753===== test_reject_lu_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]754
755full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]756talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]757
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]758===== test_reject_cm_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]759---
760- Subscriber does a normal LU
761- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]762 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]763 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]764DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]765DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]766DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]767DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]768DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]769DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]770DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
771DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
772DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
773DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]774DREF VLR subscr unknown usage increases to: 1
775DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
776DVLR New subscr, IMSI: 901700000004620
777DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]778DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]779DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
780DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
781DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
782DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
783DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
784DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
785DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
786DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]787DVLR GSUP tx: 04010809710000004026f0
788GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]789DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
790DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
791DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]792DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]793DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
794DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]795 lu_result_sent == 0
796 llist_count(&net->subscr_conns) == 1
797- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
798<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
799DVLR GSUP rx 17: 10010809710000004026f00804036470f1
800DREF VLR subscr IMSI:901700000004620 usage increases to: 2
801DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]802DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]803DVLR GSUP tx: 12010809710000004026f0
804GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
805DREF VLR subscr MSISDN:46071 usage decreases to: 1
806<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
807 lu_result_sent == 0
808- HLR also sends GSUP _UPDATE_LOCATION_RESULT
809<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
810DVLR GSUP rx 11: 06010809710000004026f0
811DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]812DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
813DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
814DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
815DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
816DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
817DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
818DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
819DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
820DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
821DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
822DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
823DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
824DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
825DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
826DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
827DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
828DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
829DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
830DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
831DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
832DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
833DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]834- sending LU Accept for MSISDN:46071
835DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]836DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
837DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
838DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
839DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
840DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
841DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
842DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
843DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
844DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
845DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
846DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]847DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]848DREF VLR subscr MSISDN:46071 usage increases to: 4
849DREF VLR subscr MSISDN:46071 usage decreases to: 3
850- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]851DREF VLR subscr MSISDN:46071 usage decreases to: 2
852<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
853 bssap_clear_sent == 1
854- LU was successful, and the conn has already been closed
855 lu_result_sent == 1
856- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]857DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]858DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
859DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
860DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
861DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
862DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
863DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
864DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
865DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]866DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]867DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]868DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
869DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]870 llist_count(&net->subscr_conns) == 0
871---
872- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]873 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]874 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]875DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]876DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]877DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]878DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]879DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
880DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
881DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
882DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
883DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]884DREF VLR subscr MSISDN:46071 usage increases to: 2
885DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]886DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
887DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
888DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
889DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
890DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
891DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
892DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]893DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]894DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]895DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]896- sending CM Service Accept for MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]897DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]898DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9: compl_l3,cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]899DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
900DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]901DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]902DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
903DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]904DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]905 cm_service_result_sent == 1
906msc_subscr_conn_is_accepted() == true
907- A second CM Service Request on the same conn is accepted without another auth dance
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]908 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]909DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]910DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]911DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
912DMM MSISDN:46071: re-using already accepted connection
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]913DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]914- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]915DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]916 cm_service_result_sent == 1
917 llist_count(&net->subscr_conns) == 1
918---
919- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]920 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]921DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]922DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]923DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
924DREF VLR subscr MSISDN:46071 usage increases to: 3
925DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]926DREF VLR subscr MSISDN:46071 usage increases to: 4
927DREF VLR subscr MSISDN:46071 usage decreases to: 3
928DREF VLR subscr MSISDN:46071 usage decreases to: 2
929DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]930DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE
931DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]932DREF MSISDN:46071: MSC conn use + release == 3 (0x10a: dtap,cm_service,release)
933DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102: dtap,release)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]934DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]935DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]936- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]937DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]938 bssap_clear_sent == 1
939- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]940DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]941DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
942DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
943DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]944DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
945DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
946DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
947DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]948DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]949DREF VLR subscr MSISDN:46071 usage decreases to: 0
950DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]951DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
952DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]953 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]954===== test_reject_cm_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]955
956full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]957talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]958
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]959===== test_reject_paging_resp_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]960---
961- Subscriber does a normal LU
962- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]963 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]964 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]965DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]966DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]967DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]968DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]969DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]970DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]971DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
972DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
973DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
974DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]975DREF VLR subscr unknown usage increases to: 1
976DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
977DVLR New subscr, IMSI: 901700000004620
978DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]979DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]980DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
981DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
982DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
983DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
984DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
985DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
986DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
987DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]988DVLR GSUP tx: 04010809710000004026f0
989GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]990DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
991DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
992DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]993DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]994DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
995DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]996 lu_result_sent == 0
997 llist_count(&net->subscr_conns) == 1
998- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
999<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1000DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1001DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1002DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1003DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1004DVLR GSUP tx: 12010809710000004026f0
1005GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1006DREF VLR subscr MSISDN:46071 usage decreases to: 1
1007<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1008 lu_result_sent == 0
1009- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1010<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1011DVLR GSUP rx 11: 06010809710000004026f0
1012DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1013DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1014DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1015DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1016DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1017DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1018DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1019DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1020DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1021DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1022DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1023DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1024DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1025DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1026DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1027DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1028DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1029DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1030DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1031DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1032DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1033DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1034DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1035- sending LU Accept for MSISDN:46071
1036DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1037DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1038DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1039DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1040DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1041DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1042DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1043DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1044DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1045DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1046DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1047DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1048DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1049DREF VLR subscr MSISDN:46071 usage increases to: 4
1050DREF VLR subscr MSISDN:46071 usage decreases to: 3
1051- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1052DREF VLR subscr MSISDN:46071 usage decreases to: 2
1053<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1054 bssap_clear_sent == 1
1055- LU was successful, and the conn has already been closed
1056 lu_result_sent == 1
1057- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1058DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1059DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1060DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1061DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1062DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1063DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1064DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1065DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1066DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1067DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1068DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1069DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1070DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1071 llist_count(&net->subscr_conns) == 0
1072---
1073- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1074 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1075 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1076DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1077DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1078DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1079DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1080DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1081DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
1082DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
1083DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1084DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1085DREF VLR subscr MSISDN:46071 usage increases to: 2
1086DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1087DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1088DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1089DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1090DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1091DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1092DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1093DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1094DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1095DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1096DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1097- sending CM Service Accept for MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1098DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1099DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9: compl_l3,cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1100DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1101DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1102DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1103DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1104DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1105DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1106 cm_service_result_sent == 1
1107msc_subscr_conn_is_accepted() == true
1108---
1109- An erratic Paging Response on the same conn is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1110 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1111DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1112DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1113DMM Ignoring Paging Response, conn already established
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1114DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1115 llist_count(&net->subscr_conns) == 1
1116---
1117- The original CM Service Request can conclude
1118- a USSD request is serviced
1119 expecting USSD:
1120 Your extension is 46071
Vadim Yanitskiy7d7ee422018-04-17 19:23:18 +0700[diff] [blame]1121 MSC <--RAN_GERAN_A-- MS: GSM0480_MTYPE_REGISTER
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1122DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Vadim Yanitskiy7d7ee422018-04-17 19:23:18 +0700[diff] [blame]1123DRLL Dispatching 04.08 message GSM0480_MTYPE_REGISTER (0xb:0x3b)
Vadim Yanitskiy10c64192018-04-17 19:17:11 +0700[diff] [blame^]1124DMM Received SS/USSD data (trans_id=8, msg_type=GSM0480_MTYPE_REGISTER)
1125DMM -> (new transaction)
1126DCC (ti 08 sub MSISDN:46071 callref 20000001) New transaction
1127DREF VLR subscr MSISDN:46071 usage increases to: 3
1128DREF MSISDN:46071: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_nc_ss)
Vadim Yanitskiy7d7ee422018-04-17 19:23:18 +0700[diff] [blame]1129DMM MSISDN:46071: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false
Vadim Yanitskiy10c64192018-04-17 19:17:11 +0700[diff] [blame^]1130DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1131DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1132DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1133DMM USSD: Own number requested
1134DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1135DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Vadim Yanitskiy7d7ee422018-04-17 19:23:18 +0700[diff] [blame]1136- DTAP --RAN_GERAN_A--> MS: GSM0480_MTYPE_RELEASE_COMPLETE: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1137- DTAP matches expected message
Vadim Yanitskiy10c64192018-04-17 19:17:11 +0700[diff] [blame^]1138DREF VLR subscr MSISDN:46071 usage decreases to: 2
1139DREF MSISDN:46071: MSC conn use - trans_nc_ss == 1 (0x2: dtap)
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1140DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1141DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1142DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1143DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1144DREF VLR subscr MSISDN:46071 usage increases to: 3
1145DREF VLR subscr MSISDN:46071 usage decreases to: 2
1146- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1147 bssap_clear_sent == 1
1148- all requests serviced, conn has been released
1149- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1150DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1151DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1152DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1153DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1154DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1155DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
1156DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1157DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1158DRLL MSISDN:46071: Freeing subscriber connection
1159DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1160DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1161DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1162 llist_count(&net->subscr_conns) == 0
1163DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1164===== test_reject_paging_resp_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1165
1166full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1167talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1168
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1169===== test_reject_lu_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1170---
1171- Subscriber does a normal LU
1172- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1173 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1174 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1175DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1176DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1177DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1178DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1179DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1180DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1181DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
1182DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
1183DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1184DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1185DREF VLR subscr unknown usage increases to: 1
1186DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1187DVLR New subscr, IMSI: 901700000004620
1188DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1189DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1190DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1191DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1192DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1193DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1194DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1195DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1196DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1197DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1198DVLR GSUP tx: 04010809710000004026f0
1199GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1200DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1201DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1202DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1203DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1204DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1205DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1206 lu_result_sent == 0
1207 llist_count(&net->subscr_conns) == 1
1208- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1209<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1210DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1211DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1212DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1213DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1214DVLR GSUP tx: 12010809710000004026f0
1215GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1216DREF VLR subscr MSISDN:46071 usage decreases to: 1
1217<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1218 lu_result_sent == 0
1219- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1220<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1221DVLR GSUP rx 11: 06010809710000004026f0
1222DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1223DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1224DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1225DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1226DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1227DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1228DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1229DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1230DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1231DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1232DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1233DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1234DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1235DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1236DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1237DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1238DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1239DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1240DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1241DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1242DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1243DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1244DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1245- sending LU Accept for MSISDN:46071
1246DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1247DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1248DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1249DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1250DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1251DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1252DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1253DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1254DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1255DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1256DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1257DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1258DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1259DREF VLR subscr MSISDN:46071 usage increases to: 4
1260DREF VLR subscr MSISDN:46071 usage decreases to: 3
1261- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1262DREF VLR subscr MSISDN:46071 usage decreases to: 2
1263<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1264 bssap_clear_sent == 1
1265- LU was successful, and the conn has already been closed
1266 lu_result_sent == 1
1267- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1268DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1269DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1270DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1271DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1272DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1273DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1274DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1275DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1276DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1277DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1278DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1279DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1280DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1281 llist_count(&net->subscr_conns) == 0
1282---
1283- an SMS is sent, MS is paged
1284DREF VLR subscr MSISDN:46071 usage increases to: 2
1285 llist_count(&vsub->cs.requests) == 0
1286DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1287DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1288 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1289 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1290DREF VLR subscr MSISDN:46071 usage increases to: 4
1291 llist_count(&vsub->cs.requests) == 1
1292DREF VLR subscr MSISDN:46071 usage decreases to: 3
1293 paging_sent == 1
1294 paging_stopped == 0
1295- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1296 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1297 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1298DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1299DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1300DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1301DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1302DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1303DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
1304DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
1305DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1306DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1307DREF VLR subscr MSISDN:46071 usage increases to: 4
1308DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1309DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1310DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1311DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1312DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1313DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1314DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1315DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1316DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1317DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1318DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1319DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1320DPAG Paging success for MSISDN:46071 (event=0)
1321DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]1322DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1323DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1324DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1325DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1326- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1327- DTAP matches expected message
1328DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1329DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1330DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1331DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1332DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1333DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1334DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1335 dtap_tx_confirmed == 1
1336 paging_stopped == 1
1337- conn is still open to wait for SMS ack dance
1338 llist_count(&net->subscr_conns) == 1
1339---
1340- MS sends erratic LU Request, which is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1341 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1342DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1343DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1344DMM Cannot accept another LU, conn already established; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1345DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1346 lu_result_sent == 0
1347 llist_count(&net->subscr_conns) == 1
1348- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1349 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1350DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1351DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1352DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1353DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1354DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1355 llist_count(&net->subscr_conns) == 1
1356- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1357 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1358DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1359DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1360DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1361DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1362- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1363- DTAP matches expected message
1364DREF VLR subscr MSISDN:46071 usage decreases to: 3
1365DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1366DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2: dtap)
1367DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1368DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1369DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1370DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1371DREF VLR subscr MSISDN:46071 usage increases to: 3
1372DREF VLR subscr MSISDN:46071 usage decreases to: 2
1373- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1374 dtap_tx_confirmed == 1
1375 bssap_clear_sent == 1
1376- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1377DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1378DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1379DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1380DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1381DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1382DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
1383DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1384DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1385DRLL MSISDN:46071: Freeing subscriber connection
1386DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1387DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1388DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1389- SMS is done
1390 llist_count(&net->subscr_conns) == 0
1391DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1392===== test_reject_lu_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1393
1394full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1395talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1396
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1397===== test_accept_cm_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1398---
1399- Subscriber does a normal LU
1400- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1401 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1402 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1403DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1404DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1405DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1406DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1407DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1408DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1409DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
1410DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
1411DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1412DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1413DREF VLR subscr unknown usage increases to: 1
1414DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1415DVLR New subscr, IMSI: 901700000004620
1416DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1417DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1418DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1419DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1420DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1421DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1422DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1423DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1424DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1425DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1426DVLR GSUP tx: 04010809710000004026f0
1427GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1428DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1429DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1430DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1431DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1432DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1433DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1434 lu_result_sent == 0
1435 llist_count(&net->subscr_conns) == 1
1436- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1437<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1438DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1439DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1440DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1441DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1442DVLR GSUP tx: 12010809710000004026f0
1443GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1444DREF VLR subscr MSISDN:46071 usage decreases to: 1
1445<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1446 lu_result_sent == 0
1447- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1448<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1449DVLR GSUP rx 11: 06010809710000004026f0
1450DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1451DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1452DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1453DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1454DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1455DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1456DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1457DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1458DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1459DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1460DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1461DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1462DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1463DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1464DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1465DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1466DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1467DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1468DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1469DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1470DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1471DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1472DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1473- sending LU Accept for MSISDN:46071
1474DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1475DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1476DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1477DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1478DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1479DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1480DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1481DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1482DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1483DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1484DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1485DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1486DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1487DREF VLR subscr MSISDN:46071 usage increases to: 4
1488DREF VLR subscr MSISDN:46071 usage decreases to: 3
1489- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1490DREF VLR subscr MSISDN:46071 usage decreases to: 2
1491<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1492 bssap_clear_sent == 1
1493- LU was successful, and the conn has already been closed
1494 lu_result_sent == 1
1495- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1496DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1497DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1498DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1499DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1500DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1501DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1502DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1503DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1504DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1505DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1506DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1507DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1508DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1509 llist_count(&net->subscr_conns) == 0
1510---
1511- an SMS is sent, MS is paged
1512DREF VLR subscr MSISDN:46071 usage increases to: 2
1513 llist_count(&vsub->cs.requests) == 0
1514DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1515DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1516 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1517 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1518DREF VLR subscr MSISDN:46071 usage increases to: 4
1519 llist_count(&vsub->cs.requests) == 1
1520DREF VLR subscr MSISDN:46071 usage decreases to: 3
1521 paging_sent == 1
1522 paging_stopped == 0
1523- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1524 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1525 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1526DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1527DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1528DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1529DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1530DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1531DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
1532DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
1533DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1534DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1535DREF VLR subscr MSISDN:46071 usage increases to: 4
1536DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1537DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1538DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1539DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1540DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1541DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1542DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1543DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1544DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1545DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1546DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1547DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1548DPAG Paging success for MSISDN:46071 (event=0)
1549DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]1550DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1551DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1552DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1553DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1554- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1555- DTAP matches expected message
1556DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1557DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1558DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1559DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1560DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1561DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1562DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1563 dtap_tx_confirmed == 1
1564 paging_stopped == 1
1565- conn is still open to wait for SMS ack dance
1566 llist_count(&net->subscr_conns) == 1
1567---
1568- CM Service Request during open connection is accepted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1569 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1570DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1571DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1572DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
1573DMM MSISDN:46071: re-using already accepted connection
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1574DREF MSISDN:46071: MSC conn use + cm_service == 3 (0x2a: dtap,cm_service,trans_sms)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1575DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1576- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1577DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28: cm_service,trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1578 cm_service_result_sent == 1
1579 llist_count(&net->subscr_conns) == 1
1580 g_conn->received_cm_service_request == 1
1581- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1582 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1583DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a: dtap,cm_service,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1584DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1585DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1586DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1587DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28: cm_service,trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1588 llist_count(&net->subscr_conns) == 1
1589- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1590 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1591DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a: dtap,cm_service,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1592DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1593DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1594DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1595- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1596- DTAP matches expected message
1597DREF VLR subscr MSISDN:46071 usage decreases to: 3
1598DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1599DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0xa: dtap,cm_service)
1600DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1601 dtap_tx_confirmed == 1
1602- SMS is done
1603 llist_count(&net->subscr_conns) == 1
1604---
1605- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1606 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1607DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1608DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1609DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1610DREF VLR subscr MSISDN:46071 usage increases to: 3
1611DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1612DREF VLR subscr MSISDN:46071 usage increases to: 4
1613DREF VLR subscr MSISDN:46071 usage decreases to: 3
1614DREF VLR subscr MSISDN:46071 usage decreases to: 2
1615DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1616DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
1617DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1618DREF MSISDN:46071: MSC conn use + release == 3 (0x10a: dtap,cm_service,release)
1619DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102: dtap,release)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1620DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1621DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1622- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1623DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1624 bssap_clear_sent == 1
1625- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1626DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1627DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1628DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1629DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1630DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1631DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
1632DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1633DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1634DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1635DREF VLR subscr MSISDN:46071 usage decreases to: 0
1636DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1637DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1638DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1639 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1640===== test_accept_cm_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1641
1642full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1643talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1644
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1645===== test_reject_paging_resp_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1646---
1647- Subscriber does a normal LU
1648- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1649 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1650 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1651DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1652DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1653DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1654DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1655DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1656DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1657DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
1658DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
1659DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1660DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1661DREF VLR subscr unknown usage increases to: 1
1662DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1663DVLR New subscr, IMSI: 901700000004620
1664DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1665DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1666DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1667DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1668DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1669DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1670DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1671DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1672DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1673DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1674DVLR GSUP tx: 04010809710000004026f0
1675GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1676DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1677DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1678DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1679DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1680DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1681DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1682 lu_result_sent == 0
1683 llist_count(&net->subscr_conns) == 1
1684- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1685<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1686DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1687DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1688DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1689DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1690DVLR GSUP tx: 12010809710000004026f0
1691GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1692DREF VLR subscr MSISDN:46071 usage decreases to: 1
1693<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1694 lu_result_sent == 0
1695- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1696<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1697DVLR GSUP rx 11: 06010809710000004026f0
1698DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1699DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1700DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1701DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1702DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1703DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1704DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1705DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1706DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1707DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1708DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1709DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1710DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1711DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1712DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1713DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1714DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1715DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1716DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1717DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1718DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1719DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1720DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1721- sending LU Accept for MSISDN:46071
1722DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1723DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1724DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1725DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1726DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1727DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1728DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1729DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1730DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1731DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1732DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1733DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1734DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1735DREF VLR subscr MSISDN:46071 usage increases to: 4
1736DREF VLR subscr MSISDN:46071 usage decreases to: 3
1737- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1738DREF VLR subscr MSISDN:46071 usage decreases to: 2
1739<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1740 bssap_clear_sent == 1
1741- LU was successful, and the conn has already been closed
1742 lu_result_sent == 1
1743- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1744DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1745DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1746DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1747DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1748DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1749DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1750DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1751DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1752DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1753DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1754DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1755DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1756DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1757 llist_count(&net->subscr_conns) == 0
1758---
1759- an SMS is sent, MS is paged
1760DREF VLR subscr MSISDN:46071 usage increases to: 2
1761 llist_count(&vsub->cs.requests) == 0
1762DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1763DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1764 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1765 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1766DREF VLR subscr MSISDN:46071 usage increases to: 4
1767 llist_count(&vsub->cs.requests) == 1
1768DREF VLR subscr MSISDN:46071 usage decreases to: 3
1769 paging_sent == 1
1770 paging_stopped == 0
1771- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1772 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1773 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1774DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1775DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1776DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1777DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1778DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1779DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
1780DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
1781DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1782DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1783DREF VLR subscr MSISDN:46071 usage increases to: 4
1784DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1785DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1786DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1787DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1788DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1789DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1790DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1791DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1792DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1793DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1794DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1795DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1796DPAG Paging success for MSISDN:46071 (event=0)
1797DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]1798DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1799DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1800DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1801DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1802- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1803- DTAP matches expected message
1804DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1805DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1806DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1807DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1808DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1809DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1810DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1811 dtap_tx_confirmed == 1
1812 paging_stopped == 1
1813- conn is still open to wait for SMS ack dance
1814 llist_count(&net->subscr_conns) == 1
1815---
1816- MS sends another erratic Paging Response which is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1817 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1818DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1819DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1820DMM Ignoring Paging Response, conn already established
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1821DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1822- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1823 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1824DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1825DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1826DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1827DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1828DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1829 llist_count(&net->subscr_conns) == 1
1830- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1831 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1832DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1833DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1834DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1835DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1836- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1837- DTAP matches expected message
1838DREF VLR subscr MSISDN:46071 usage decreases to: 3
1839DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1840DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2: dtap)
1841DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1842DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1843DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1844DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1845DREF VLR subscr MSISDN:46071 usage increases to: 3
1846DREF VLR subscr MSISDN:46071 usage decreases to: 2
1847- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1848 dtap_tx_confirmed == 1
1849 bssap_clear_sent == 1
1850- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1851DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1852DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1853DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1854DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1855DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1856DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
1857DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1858DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1859DRLL MSISDN:46071: Freeing subscriber connection
1860DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1861DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1862DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1863- SMS is done
1864 llist_count(&net->subscr_conns) == 0
1865DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1866===== test_reject_paging_resp_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1867
1868full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1869talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1870
1871full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1872talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1873