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