Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 36115c9d9aa3efa8b98d75632d08510ff368b38c / . / tests / msc_vlr / msc_vlr_test_reject_concurrency.err
blob: 84436d3ab58b6ee40f79385c0902ba1adf529559 [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
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]705DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]706 cm_service_result_sent == 1
707msc_subscr_conn_is_accepted() == true
708- A LU request on an open conn is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]709 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]710DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]711DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]712DMM 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]713DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]714 lu_result_sent == 0
715 llist_count(&net->subscr_conns) == 1
716---
717- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]718 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]719DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]720DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]721DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
722DREF VLR subscr MSISDN:46071 usage increases to: 3
723DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]724DREF VLR subscr MSISDN:46071 usage increases to: 4
725DREF VLR subscr MSISDN:46071 usage decreases to: 3
726DREF VLR subscr MSISDN:46071 usage decreases to: 2
727DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]728DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE
729DMM 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]730DREF MSISDN:46071: MSC conn use + release == 3 (0x10a: dtap,cm_service,release)
731DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102: dtap,release)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]732DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]733DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]734- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]735DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]736 bssap_clear_sent == 1
737- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]738DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]739DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
740DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
741DMM 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]742DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
743DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
744DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
745DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]746DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]747DREF VLR subscr MSISDN:46071 usage decreases to: 0
748DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]749DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
750DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]751 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]752===== test_reject_lu_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]753
754full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]755talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]756
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]757===== test_reject_cm_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]758---
759- Subscriber does a normal LU
760- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]761 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]762 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]763DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]764DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]765DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]766DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]767DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]768DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]769DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
770DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
771DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
772DVLR 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]773DREF VLR subscr unknown usage increases to: 1
774DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
775DVLR New subscr, IMSI: 901700000004620
776DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]777DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]778DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
779DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
780DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
781DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
782DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
783DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
784DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
785DVLR 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]786DVLR GSUP tx: 04010809710000004026f0
787GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]788DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
789DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
790DMM 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]791DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]792DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
793DMM 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]794 lu_result_sent == 0
795 llist_count(&net->subscr_conns) == 1
796- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
797<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
798DVLR GSUP rx 17: 10010809710000004026f00804036470f1
799DREF VLR subscr IMSI:901700000004620 usage increases to: 2
800DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]801DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]802DVLR GSUP tx: 12010809710000004026f0
803GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
804DREF VLR subscr MSISDN:46071 usage decreases to: 1
805<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
806 lu_result_sent == 0
807- HLR also sends GSUP _UPDATE_LOCATION_RESULT
808<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
809DVLR GSUP rx 11: 06010809710000004026f0
810DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]811DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
812DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
813DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
814DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
815DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
816DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
817DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
818DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
819DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
820DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
821DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
822DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
823DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
824DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
825DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
826DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
827DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
828DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
829DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
830DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
831DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
832DVLR 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]833- sending LU Accept for MSISDN:46071
834DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]835DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
836DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
837DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
838DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
839DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
840DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
841DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
842DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
843DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
844DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
845DMM 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]846DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]847DREF VLR subscr MSISDN:46071 usage increases to: 4
848DREF VLR subscr MSISDN:46071 usage decreases to: 3
849- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]850DREF VLR subscr MSISDN:46071 usage decreases to: 2
851<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
852 bssap_clear_sent == 1
853- LU was successful, and the conn has already been closed
854 lu_result_sent == 1
855- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]856DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]857DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
858DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
859DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
860DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
861DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
862DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
863DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
864DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]865DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]866DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]867DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
868DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]869 llist_count(&net->subscr_conns) == 0
870---
871- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]872 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]873 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]874DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]875DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]876DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]877DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]878DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
879DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
880DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
881DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
882DVLR 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]883DREF VLR subscr MSISDN:46071 usage increases to: 2
884DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]885DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
886DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
887DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
888DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
889DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
890DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
891DVLR 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]892DVLR 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]893DVLR 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]894DVLR 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]895- sending CM Service Accept for MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]896DMM 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]897DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9: compl_l3,cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]898DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
899DMM 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]900DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]901DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]902DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]903 cm_service_result_sent == 1
904msc_subscr_conn_is_accepted() == true
905- 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]906 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]907DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]908DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]909DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
910DMM MSISDN:46071: re-using already accepted connection
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]911DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]912- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]913DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]914 cm_service_result_sent == 1
915 llist_count(&net->subscr_conns) == 1
916---
917- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]918 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]919DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]920DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]921DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
922DREF VLR subscr MSISDN:46071 usage increases to: 3
923DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]924DREF VLR subscr MSISDN:46071 usage increases to: 4
925DREF VLR subscr MSISDN:46071 usage decreases to: 3
926DREF VLR subscr MSISDN:46071 usage decreases to: 2
927DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]928DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE
929DMM 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]930DREF MSISDN:46071: MSC conn use + release == 3 (0x10a: dtap,cm_service,release)
931DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102: dtap,release)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]932DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]933DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]934- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]935DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]936 bssap_clear_sent == 1
937- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]938DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]939DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
940DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
941DMM 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]942DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
943DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
944DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
945DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]946DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]947DREF VLR subscr MSISDN:46071 usage decreases to: 0
948DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]949DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
950DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]951 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]952===== test_reject_cm_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]953
954full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]955talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]956
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]957===== test_reject_paging_resp_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]958---
959- Subscriber does a normal LU
960- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]961 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]962 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]963DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]964DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]965DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]966DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]967DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]968DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]969DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
970DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
971DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
972DVLR 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]973DREF VLR subscr unknown usage increases to: 1
974DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
975DVLR New subscr, IMSI: 901700000004620
976DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]977DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]978DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
979DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
980DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
981DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
982DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
983DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
984DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
985DVLR 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]986DVLR GSUP tx: 04010809710000004026f0
987GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]988DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
989DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
990DMM 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]991DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]992DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
993DMM 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]994 lu_result_sent == 0
995 llist_count(&net->subscr_conns) == 1
996- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
997<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
998DVLR GSUP rx 17: 10010809710000004026f00804036470f1
999DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1000DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1001DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1002DVLR GSUP tx: 12010809710000004026f0
1003GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1004DREF VLR subscr MSISDN:46071 usage decreases to: 1
1005<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1006 lu_result_sent == 0
1007- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1008<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1009DVLR GSUP rx 11: 06010809710000004026f0
1010DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1011DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1012DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1013DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1014DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1015DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1016DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1017DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1018DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1019DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1020DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1021DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1022DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1023DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1024DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1025DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1026DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1027DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1028DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1029DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1030DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1031DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1032DVLR 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]1033- sending LU Accept for MSISDN:46071
1034DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1035DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1036DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1037DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1038DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1039DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1040DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1041DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1042DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1043DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1044DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1045DMM 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]1046DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1047DREF VLR subscr MSISDN:46071 usage increases to: 4
1048DREF VLR subscr MSISDN:46071 usage decreases to: 3
1049- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1050DREF VLR subscr MSISDN:46071 usage decreases to: 2
1051<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1052 bssap_clear_sent == 1
1053- LU was successful, and the conn has already been closed
1054 lu_result_sent == 1
1055- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1056DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1057DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1058DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1059DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1060DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1061DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1062DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1063DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1064DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1065DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1066DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1067DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1068DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1069 llist_count(&net->subscr_conns) == 0
1070---
1071- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1072 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1073 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1074DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1075DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1076DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1077DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1078DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1079DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
1080DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
1081DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1082DVLR 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]1083DREF VLR subscr MSISDN:46071 usage increases to: 2
1084DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1085DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1086DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1087DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1088DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1089DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1090DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1091DVLR 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]1092DVLR 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]1093DVLR 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]1094DVLR 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]1095- sending CM Service Accept for MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1096DMM 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]1097DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9: compl_l3,cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1098DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1099DMM 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]1100DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1101DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1102DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1103 cm_service_result_sent == 1
1104msc_subscr_conn_is_accepted() == true
1105---
1106- An erratic Paging Response on the same conn is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1107 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1108DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1109DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1110DMM Ignoring Paging Response, conn already established
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1111DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1112 llist_count(&net->subscr_conns) == 1
1113---
1114- The original CM Service Request can conclude
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]1115- Concluding CM Service Request
1116DREF MSISDN:46071: MSC conn use - cm_service == 0 (0x0: )
1117DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1118DMM 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]1119DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1120DREF VLR subscr MSISDN:46071 usage increases to: 3
1121DREF VLR subscr MSISDN:46071 usage decreases to: 2
1122- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1123 bssap_clear_sent == 1
1124- all requests serviced, conn has been released
1125- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1126DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1127DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1128DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1129DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1130DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1131DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
1132DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1133DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1134DRLL MSISDN:46071: Freeing subscriber connection
1135DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1136DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1137DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1138 llist_count(&net->subscr_conns) == 0
1139DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1140===== test_reject_paging_resp_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1141
1142full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1143talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1144
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1145===== test_reject_lu_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1146---
1147- Subscriber does a normal LU
1148- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1149 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1150 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1151DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1152DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1153DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1154DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1155DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1156DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1157DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
1158DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
1159DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1160DVLR 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]1161DREF VLR subscr unknown usage increases to: 1
1162DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1163DVLR New subscr, IMSI: 901700000004620
1164DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1165DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1166DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1167DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1168DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1169DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1170DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1171DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1172DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1173DVLR 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]1174DVLR GSUP tx: 04010809710000004026f0
1175GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1176DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1177DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1178DMM 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]1179DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1180DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1181DMM 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]1182 lu_result_sent == 0
1183 llist_count(&net->subscr_conns) == 1
1184- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1185<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1186DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1187DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1188DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1189DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1190DVLR GSUP tx: 12010809710000004026f0
1191GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1192DREF VLR subscr MSISDN:46071 usage decreases to: 1
1193<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1194 lu_result_sent == 0
1195- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1196<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1197DVLR GSUP rx 11: 06010809710000004026f0
1198DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1199DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1200DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1201DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1202DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1203DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1204DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1205DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1206DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1207DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1208DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1209DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1210DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1211DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1212DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1213DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1214DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1215DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1216DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1217DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1218DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1219DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1220DVLR 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]1221- sending LU Accept for MSISDN:46071
1222DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1223DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1224DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1225DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1226DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1227DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1228DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1229DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1230DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1231DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1232DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1233DMM 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]1234DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1235DREF VLR subscr MSISDN:46071 usage increases to: 4
1236DREF VLR subscr MSISDN:46071 usage decreases to: 3
1237- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1238DREF VLR subscr MSISDN:46071 usage decreases to: 2
1239<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1240 bssap_clear_sent == 1
1241- LU was successful, and the conn has already been closed
1242 lu_result_sent == 1
1243- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1244DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1245DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1246DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1247DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1248DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1249DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1250DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1251DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1252DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1253DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1254DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1255DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1256DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1257 llist_count(&net->subscr_conns) == 0
1258---
1259- an SMS is sent, MS is paged
1260DREF VLR subscr MSISDN:46071 usage increases to: 2
1261 llist_count(&vsub->cs.requests) == 0
1262DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1263DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1264 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1265 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1266DREF VLR subscr MSISDN:46071 usage increases to: 4
1267 llist_count(&vsub->cs.requests) == 1
1268DREF VLR subscr MSISDN:46071 usage decreases to: 3
1269 paging_sent == 1
1270 paging_stopped == 0
1271- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1272 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1273 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1274DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1275DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1276DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1277DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1278DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1279DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
1280DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
1281DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1282DVLR 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]1283DREF VLR subscr MSISDN:46071 usage increases to: 4
1284DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1285DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1286DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1287DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1288DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1289DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1290DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1291DVLR 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]1292DVLR 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]1293DVLR 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]1294DVLR 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]1295DMM 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]1296DPAG Paging success for MSISDN:46071 (event=0)
1297DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]1298DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1299DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1300DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1301DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1302- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1303- DTAP matches expected message
1304DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1305DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1306DMM 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]1307DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1308DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1309DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1310 dtap_tx_confirmed == 1
1311 paging_stopped == 1
1312- conn is still open to wait for SMS ack dance
1313 llist_count(&net->subscr_conns) == 1
1314---
1315- MS sends erratic LU Request, which is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1316 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1317DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1318DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1319DMM 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]1320DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1321 lu_result_sent == 0
1322 llist_count(&net->subscr_conns) == 1
1323- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1324 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1325DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1326DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1327DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1328DMM 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]1329DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1330 llist_count(&net->subscr_conns) == 1
1331- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1332 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1333DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1334DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1335DMM 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]1336DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1337- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1338- DTAP matches expected message
1339DREF VLR subscr MSISDN:46071 usage decreases to: 3
1340DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1341DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2: dtap)
1342DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1343DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1344DMM 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]1345DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1346DREF VLR subscr MSISDN:46071 usage increases to: 3
1347DREF VLR subscr MSISDN:46071 usage decreases to: 2
1348- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1349 dtap_tx_confirmed == 1
1350 bssap_clear_sent == 1
1351- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1352DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1353DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1354DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1355DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1356DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1357DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
1358DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1359DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1360DRLL MSISDN:46071: Freeing subscriber connection
1361DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1362DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1363DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1364- SMS is done
1365 llist_count(&net->subscr_conns) == 0
1366DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1367===== test_reject_lu_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1368
1369full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1370talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1371
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1372===== test_accept_cm_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1373---
1374- Subscriber does a normal LU
1375- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1376 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1377 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1378DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1379DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1380DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1381DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1382DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1383DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1384DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
1385DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
1386DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1387DVLR 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]1388DREF VLR subscr unknown usage increases to: 1
1389DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1390DVLR New subscr, IMSI: 901700000004620
1391DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1392DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1393DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1394DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1395DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1396DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1397DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1398DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1399DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1400DVLR 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]1401DVLR GSUP tx: 04010809710000004026f0
1402GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1403DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1404DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1405DMM 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]1406DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1407DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1408DMM 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]1409 lu_result_sent == 0
1410 llist_count(&net->subscr_conns) == 1
1411- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1412<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1413DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1414DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1415DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1416DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1417DVLR GSUP tx: 12010809710000004026f0
1418GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1419DREF VLR subscr MSISDN:46071 usage decreases to: 1
1420<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1421 lu_result_sent == 0
1422- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1423<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1424DVLR GSUP rx 11: 06010809710000004026f0
1425DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1426DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1427DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1428DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1429DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1430DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1431DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1432DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1433DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1434DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1435DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1436DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1437DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1438DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1439DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1440DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1441DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1442DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1443DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1444DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1445DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1446DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1447DVLR 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]1448- sending LU Accept for MSISDN:46071
1449DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1450DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1451DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1452DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1453DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1454DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1455DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1456DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1457DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1458DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1459DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1460DMM 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]1461DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1462DREF VLR subscr MSISDN:46071 usage increases to: 4
1463DREF VLR subscr MSISDN:46071 usage decreases to: 3
1464- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1465DREF VLR subscr MSISDN:46071 usage decreases to: 2
1466<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1467 bssap_clear_sent == 1
1468- LU was successful, and the conn has already been closed
1469 lu_result_sent == 1
1470- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1471DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1472DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1473DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1474DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1475DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1476DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1477DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1478DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1479DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1480DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1481DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1482DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1483DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1484 llist_count(&net->subscr_conns) == 0
1485---
1486- an SMS is sent, MS is paged
1487DREF VLR subscr MSISDN:46071 usage increases to: 2
1488 llist_count(&vsub->cs.requests) == 0
1489DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1490DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1491 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1492 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1493DREF VLR subscr MSISDN:46071 usage increases to: 4
1494 llist_count(&vsub->cs.requests) == 1
1495DREF VLR subscr MSISDN:46071 usage decreases to: 3
1496 paging_sent == 1
1497 paging_stopped == 0
1498- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1499 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1500 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1501DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1502DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1503DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1504DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1505DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1506DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
1507DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
1508DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1509DVLR 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]1510DREF VLR subscr MSISDN:46071 usage increases to: 4
1511DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1512DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1513DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1514DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1515DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1516DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1517DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1518DVLR 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]1519DVLR 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]1520DVLR 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]1521DVLR 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]1522DMM 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]1523DPAG Paging success for MSISDN:46071 (event=0)
1524DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]1525DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1526DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1527DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1528DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1529- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1530- DTAP matches expected message
1531DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1532DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1533DMM 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]1534DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1535DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1536DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1537 dtap_tx_confirmed == 1
1538 paging_stopped == 1
1539- conn is still open to wait for SMS ack dance
1540 llist_count(&net->subscr_conns) == 1
1541---
1542- CM Service Request during open connection is accepted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1543 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1544DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1545DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1546DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
1547DMM MSISDN:46071: re-using already accepted connection
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1548DREF MSISDN:46071: MSC conn use + cm_service == 3 (0x2a: dtap,cm_service,trans_sms)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1549DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1550- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1551DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28: cm_service,trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1552 cm_service_result_sent == 1
1553 llist_count(&net->subscr_conns) == 1
1554 g_conn->received_cm_service_request == 1
1555- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1556 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1557DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a: dtap,cm_service,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1558DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1559DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1560DMM 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]1561DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28: cm_service,trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1562 llist_count(&net->subscr_conns) == 1
1563- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1564 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1565DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a: dtap,cm_service,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1566DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1567DMM 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]1568DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1569- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1570- DTAP matches expected message
1571DREF VLR subscr MSISDN:46071 usage decreases to: 3
1572DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1573DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0xa: dtap,cm_service)
1574DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8: cm_service)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1575 dtap_tx_confirmed == 1
1576- SMS is done
1577 llist_count(&net->subscr_conns) == 1
1578---
1579- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1580 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1581DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1582DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1583DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1584DREF VLR subscr MSISDN:46071 usage increases to: 3
1585DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1586DREF VLR subscr MSISDN:46071 usage increases to: 4
1587DREF VLR subscr MSISDN:46071 usage decreases to: 3
1588DREF VLR subscr MSISDN:46071 usage decreases to: 2
1589DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1590DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
1591DMM 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]1592DREF MSISDN:46071: MSC conn use + release == 3 (0x10a: dtap,cm_service,release)
1593DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102: dtap,release)
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1594DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1595DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1596- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1597DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1598 bssap_clear_sent == 1
1599- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1600DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1601DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1602DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1603DMM 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]1604DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1605DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
1606DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1607DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1608DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1609DREF VLR subscr MSISDN:46071 usage decreases to: 0
1610DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1611DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1612DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1613 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1614===== test_accept_cm_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1615
1616full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1617talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1618
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1619===== test_reject_paging_resp_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1620---
1621- Subscriber does a normal LU
1622- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1623 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1624 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1625DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1626DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1627DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1628DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1629DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1630DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1631DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
1632DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
1633DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1634DVLR 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]1635DREF VLR subscr unknown usage increases to: 1
1636DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1637DVLR New subscr, IMSI: 901700000004620
1638DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1639DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1640DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1641DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1642DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1643DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1644DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1645DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1646DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1647DVLR 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]1648DVLR GSUP tx: 04010809710000004026f0
1649GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1650DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1651DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1652DMM 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]1653DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1654DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1655DMM 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]1656 lu_result_sent == 0
1657 llist_count(&net->subscr_conns) == 1
1658- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1659<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1660DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1661DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1662DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1663DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1664DVLR GSUP tx: 12010809710000004026f0
1665GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1666DREF VLR subscr MSISDN:46071 usage decreases to: 1
1667<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1668 lu_result_sent == 0
1669- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1670<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1671DVLR GSUP rx 11: 06010809710000004026f0
1672DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1673DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1674DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1675DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1676DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1677DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1678DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1679DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1680DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1681DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1682DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1683DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
1684DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1685DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1686DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1687DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
1688DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1689DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1690DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1691DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
1692DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1693DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1694DVLR 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]1695- sending LU Accept for MSISDN:46071
1696DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1697DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1698DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1699DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1700DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
1701DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1702DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1703DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1704DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1705DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1706DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1707DMM 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]1708DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1709DREF VLR subscr MSISDN:46071 usage increases to: 4
1710DREF VLR subscr MSISDN:46071 usage decreases to: 3
1711- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1712DREF VLR subscr MSISDN:46071 usage decreases to: 2
1713<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1714 bssap_clear_sent == 1
1715- LU was successful, and the conn has already been closed
1716 lu_result_sent == 1
1717- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1718DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1719DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1720DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1721DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1722DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1723DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
1724DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1725DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
1726DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1727DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1728DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1729DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1730DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1731 llist_count(&net->subscr_conns) == 0
1732---
1733- an SMS is sent, MS is paged
1734DREF VLR subscr MSISDN:46071 usage increases to: 2
1735 llist_count(&vsub->cs.requests) == 0
1736DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1737DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1738 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1739 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1740DREF VLR subscr MSISDN:46071 usage increases to: 4
1741 llist_count(&vsub->cs.requests) == 1
1742DREF VLR subscr MSISDN:46071 usage decreases to: 3
1743 paging_sent == 1
1744 paging_stopped == 0
1745- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1746 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1747 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1748DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1749DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1750DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1751DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1752DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
1753DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
1754DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
1755DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1756DVLR 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]1757DREF VLR subscr MSISDN:46071 usage increases to: 4
1758DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1759DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1760DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1761DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1762DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1763DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1764DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1765DVLR 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]1766DVLR 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]1767DVLR 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]1768DVLR 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]1769DMM 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]1770DPAG Paging success for MSISDN:46071 (event=0)
1771DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]1772DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1773DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1774DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21: compl_l3,trans_sms)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1775DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1776- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1777- DTAP matches expected message
1778DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1779DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1780DMM 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]1781DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1782DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1783DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1784 dtap_tx_confirmed == 1
1785 paging_stopped == 1
1786- conn is still open to wait for SMS ack dance
1787 llist_count(&net->subscr_conns) == 1
1788---
1789- MS sends another erratic Paging Response which is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1790 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1791DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1792DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1793DMM Ignoring Paging Response, conn already established
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1794DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1795- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1796 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1797DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1798DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1799DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1800DMM 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]1801DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20: trans_sms)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1802 llist_count(&net->subscr_conns) == 1
1803- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1804 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1805DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22: dtap,trans_sms)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1806DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1807DMM 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]1808DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1809- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1810- DTAP matches expected message
1811DREF VLR subscr MSISDN:46071 usage decreases to: 3
1812DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1813DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2: dtap)
1814DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1815DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1816DMM 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]1817DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1818DREF VLR subscr MSISDN:46071 usage increases to: 3
1819DREF VLR subscr MSISDN:46071 usage decreases to: 2
1820- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1821 dtap_tx_confirmed == 1
1822 bssap_clear_sent == 1
1823- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1824DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1825DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1826DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1827DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1828DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1829DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
1830DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
1831DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1832DRLL MSISDN:46071: Freeing subscriber connection
1833DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1834DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1835DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1836- SMS is done
1837 llist_count(&net->subscr_conns) == 0
1838DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1839===== test_reject_paging_resp_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1840
1841full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1842talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1843
1844full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1845talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1846