blob: 0d9ef5be3483be3705cd02e7e586f93df22c98c4 [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001full 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 +01004===== test_reject_2nd_conn
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01005- Location Update Request on one connection
Neels Hofmeyr78ada642017-03-10 02:15:20 +01006 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01007 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02008DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01009DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010010DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +020011DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010012DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +010013DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010014DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
15DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
16DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
17DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
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 +020022DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010023DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
24DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
25DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
26DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
27DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
28DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
29DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
30DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
31DVLR GSUP tx: 04010809710000004026f0
32GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
33DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +020034DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
35DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
36DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
37DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
38DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010039 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 +010042 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010043 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +020044DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +010045DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010046DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +020047DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010048DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +010049DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010050DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
51DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
52DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
53DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
54DREF VLR subscr IMSI:901700000004620 usage increases to: 2
55DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: A Location Updating process is already pending for this subscriber. Aborting.
56- sending LU Reject for unknown, cause 22
57DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +020058DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +020059DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
60DREF unknown: MSC conn use + release == 2 (0x101)
61- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +020062DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
63DRR 901700000004620: internal error during Location Updating attempt
Neels Hofmeyr4068ab22018-04-01 20:55:54 +020064DREF 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 Hofmeyre3d3dc62018-03-31 00:02:14 +020069DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
70DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +020071DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010072DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
73DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
74DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
75DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
76DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +020077DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyr84da6b12016-05-20 21:59:55 +020078DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
79DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010080 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 +010088DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010089DVLR 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
98DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
99DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
100DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
101DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
102DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
103DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
104DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
105DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
106DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
107DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
108DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
109DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
110DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
111DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
112DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
113DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
114DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
115DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
116DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
117DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
118DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
119DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
120- sending LU Accept for MSISDN:46071
121DREF VLR subscr MSISDN:46071 usage increases to: 3
122DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
123DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
124DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
125DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
126DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
127DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
128DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200129DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
130DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
131DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
132DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
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 +0200137DREF 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 +0200143DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
144DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
145DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200146DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100147DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
148DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
149DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
150DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
151DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200152DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200153DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200154DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
155DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100156 llist_count(&net->subscr_conns) == 0
157DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100158===== test_reject_2nd_conn: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100159
160full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200161talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100162
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100163===== test_reject_lu_during_lu
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100164- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100165 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100166 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200167DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100168DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100169DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200170DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100171DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100172DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100173DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
174DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
175DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
176DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
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 +0200181DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100182DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
183DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
184DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
185DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
186DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
187DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
188DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
189DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
190DVLR GSUP tx: 04010809710000004026f0
191GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
192DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200193DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
194DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
195DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
196DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
197DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100198 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 +0100202 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200203DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100204DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200205DMM 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)
207DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
208DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100209 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 +0100218DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100219DVLR 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
228DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
229DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
230DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
231DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
232DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
233DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
234DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
235DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
236DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
237DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
238DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
239DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
240DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
241DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
242DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
243DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
244DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
245DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
246DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
247DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
248DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
249DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
250- sending LU Accept for MSISDN:46071
251DREF VLR subscr MSISDN:46071 usage increases to: 3
252DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
253DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
254DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
255DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
256DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
257DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
258DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200259DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
260DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
261DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
262DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
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 +0200267DREF 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 +0200273DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
274DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
275DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200276DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100277DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
278DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
279DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
280DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
281DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200282DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200283DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200284DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
285DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100286 llist_count(&net->subscr_conns) == 0
287DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100288===== test_reject_lu_during_lu: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100289
290full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200291talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100292
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100293===== test_reject_cm_during_lu
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100294- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100295 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100296 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200297DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100298DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100299DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200300DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100301DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100302DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100303DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
304DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
305DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
306DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
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 +0200311DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100312DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
313DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
314DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
315DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
316DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
317DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
318DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
319DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
320DVLR GSUP tx: 04010809710000004026f0
321GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
322DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200323DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
324DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
325DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
326DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
327DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100328 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 +0100332 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200333DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100334DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100335DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200336DMM Cannot accept CM Service Request, conn already busy establishing authenticity
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100337DMM -> CM SERVICE Reject cause: 17
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200338DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100339- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_CM_SERV_REJ: 052211
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100340- DTAP matches expected message
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200341DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
342DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
343DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100344 lu_result_sent == 0
345 cm_service_result_sent == 0
Neels Hofmeyr9fe52e42018-04-02 22:46:55 +0200346 dtap_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100347 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 +0100355DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100356DVLR 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
365DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
366DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
367DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
368DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
369DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
370DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
371DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
372DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
373DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
374DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
375DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
376DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
377DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
378DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
379DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
380DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
381DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
382DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
383DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
384DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
385DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
386DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
387- sending LU Accept for MSISDN:46071
388DREF VLR subscr MSISDN:46071 usage increases to: 3
389DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
390DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
391DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
392DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
393DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
394DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
395DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200396DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
397DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
398DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
399DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
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 +0200404DREF 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 +0200410DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
411DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
412DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200413DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100414DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
415DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
416DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
417DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
418DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200419DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200420DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200421DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
422DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100423 llist_count(&net->subscr_conns) == 0
424DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100425===== test_reject_cm_during_lu: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100426
427full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200428talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100429
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100430===== test_reject_paging_resp_during_lu
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100431- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100432 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100433 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200434DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100435DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100436DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200437DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100438DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100439DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100440DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
441DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
442DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
443DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
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 +0200448DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100449DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
450DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
451DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
452DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
453DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
454DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
455DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
456DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
457DVLR GSUP tx: 04010809710000004026f0
458GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
459DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200460DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
461DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
462DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
463DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
464DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100465 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 +0100469 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200470DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100471DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200472DMM Ignoring Paging Response, conn already busy establishing authenticity
473DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
474DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
475DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100476 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 +0100485DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100486DVLR 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
495DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
496DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
497DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
498DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
499DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
500DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
501DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
502DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
503DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
504DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
505DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
506DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
507DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
508DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
509DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
510DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
511DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
512DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
513DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
514DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
515DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
516DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
517- sending LU Accept for MSISDN:46071
518DREF VLR subscr MSISDN:46071 usage increases to: 3
519DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
520DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
521DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
522DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
523DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
524DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
525DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200526DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
527DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
528DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
529DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
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 +0200534DREF 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 +0200540DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
541DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
542DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200543DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100544DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
545DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
546DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
547DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
548DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200549DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200550DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200551DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
552DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100553 llist_count(&net->subscr_conns) == 0
554DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100555===== test_reject_paging_resp_during_lu: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100556
557full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200558talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100559
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100560===== test_reject_lu_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100561---
562- Subscriber does a normal LU
563- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100564 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100565 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200566DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100567DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100568DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200569DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100570DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100571DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100572DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
573DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
574DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
575DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
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 +0200580DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100581DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
582DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
583DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
584DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
585DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
586DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
587DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
588DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
589DVLR GSUP tx: 04010809710000004026f0
590GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
591DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200592DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
593DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
594DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
595DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
596DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100597 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 +0100604DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100605DVLR 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
614DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
615DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
616DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
617DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
618DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
619DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
620DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
621DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
622DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
623DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
624DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
625DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
626DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
627DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
628DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
629DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
630DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
631DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
632DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
633DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
634DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
635DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
636- sending LU Accept for MSISDN:46071
637DREF VLR subscr MSISDN:46071 usage increases to: 3
638DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
639DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
640DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
641DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
642DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
643DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
644DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200645DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
646DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
647DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
648DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
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 +0200653DREF 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 +0200659DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
660DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
661DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200662DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100663DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
664DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
665DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
666DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
667DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200668DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200669DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200670DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
671DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100672 llist_count(&net->subscr_conns) == 0
673---
674- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100675 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100676 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200677DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100678DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100679DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100680DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200681DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100682DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
683DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
684DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
685DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
686DREF VLR subscr MSISDN:46071 usage increases to: 2
687DREF VLR subscr MSISDN:46071 usage increases to: 3
688DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
689DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
690DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
691DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
692DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
693DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
694DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
695DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
696DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
697DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
698- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200699DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200700DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200701DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200702DMM Subscr_Conn(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 +0100703DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200704DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
705DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
706DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100707 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 +0100710 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200711DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100712DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200713DMM 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 +0100715 lu_result_sent == 0
716 llist_count(&net->subscr_conns) == 1
717---
718- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100719 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200720DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100721DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100722DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
723DREF VLR subscr MSISDN:46071 usage increases to: 3
724DMM IMSI DETACH for MSISDN:46071
725DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_ERROR)
726DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
727DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
728DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200729DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200730DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
731DREF MSISDN:46071: MSC conn use + release == 3 (0x10a)
732DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102)
733DREF VLR subscr MSISDN:46071 usage increases to: 4
734DREF VLR subscr MSISDN:46071 usage decreases to: 3
Philipp Maierfbf66102017-04-09 12:32:51 +0200735- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100736DREF VLR subscr MSISDN:46071 usage decreases to: 2
737DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200738DMM conn_close(vsub=MSISDN:46071, cause=0): already in release, ignore.
739DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
740 bssap_clear_sent == 1
741- BSS sends BSSMAP Clear Complete
742DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200743DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
744DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
745DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
746DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100747DREF VLR subscr MSISDN:46071 usage decreases to: 0
748DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200749DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
750DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100751 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100752===== test_reject_lu_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100753
754full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200755talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100756
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100757===== test_reject_cm_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100758---
759- Subscriber does a normal LU
760- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100761 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100762 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200763DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100764DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100765DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200766DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100767DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100768DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100769DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
770DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
771DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
772DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
773DREF VLR subscr unknown usage increases to: 1
774DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
775DVLR New subscr, IMSI: 901700000004620
776DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200777DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100778DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
779DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
780DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
781DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
782DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
783DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
784DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
785DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
786DVLR GSUP tx: 04010809710000004026f0
787GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
788DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200789DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
790DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
791DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
792DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
793DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100794 lu_result_sent == 0
795 llist_count(&net->subscr_conns) == 1
796- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
797<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
798DVLR GSUP rx 17: 10010809710000004026f00804036470f1
799DREF VLR subscr IMSI:901700000004620 usage increases to: 2
800DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100801DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100802DVLR GSUP tx: 12010809710000004026f0
803GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
804DREF VLR subscr MSISDN:46071 usage decreases to: 1
805<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
806 lu_result_sent == 0
807- HLR also sends GSUP _UPDATE_LOCATION_RESULT
808<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
809DVLR GSUP rx 11: 06010809710000004026f0
810DREF VLR subscr MSISDN:46071 usage increases to: 2
811DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
812DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
813DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
814DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
815DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
816DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
817DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
818DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
819DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
820DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
821DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
822DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
823DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
824DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
825DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
826DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
827DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
828DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
829DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
830DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
831DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
832DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
833- sending LU Accept for MSISDN:46071
834DREF VLR subscr MSISDN:46071 usage increases to: 3
835DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
836DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
837DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
838DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
839DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
840DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
841DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200842DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
843DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
844DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
845DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
846DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
847DREF VLR subscr MSISDN:46071 usage increases to: 4
848DREF VLR subscr MSISDN:46071 usage decreases to: 3
849- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200850DREF VLR subscr MSISDN:46071 usage decreases to: 2
851<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
852 bssap_clear_sent == 1
853- LU was successful, and the conn has already been closed
854 lu_result_sent == 1
855- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200856DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
857DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
858DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200859DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100860DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
861DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
862DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
863DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
864DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200865DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200866DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200867DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
868DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100869 llist_count(&net->subscr_conns) == 0
870---
871- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100872 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100873 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200874DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100875DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100876DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100877DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200878DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100879DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
880DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
881DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
882DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
883DREF VLR subscr MSISDN:46071 usage increases to: 2
884DREF VLR subscr MSISDN:46071 usage increases to: 3
885DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
886DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
887DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
888DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
889DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
890DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
891DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
892DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
893DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
894DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
895- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200896DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200897DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200898DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200899DMM Subscr_Conn(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 +0100900DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200901DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
902DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
903DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100904 cm_service_result_sent == 1
905msc_subscr_conn_is_accepted() == true
906- A second CM Service Request on the same conn is accepted without another auth dance
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100907 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200908DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100909DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100910DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
911DMM MSISDN:46071: re-using already accepted connection
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200912DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100913- sending CM Service Accept for MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200914DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100915 cm_service_result_sent == 1
916 llist_count(&net->subscr_conns) == 1
917---
918- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100919 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200920DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100921DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100922DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
923DREF VLR subscr MSISDN:46071 usage increases to: 3
924DMM IMSI DETACH for MSISDN:46071
925DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_ERROR)
926DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
927DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
928DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200929DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200930DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
931DREF MSISDN:46071: MSC conn use + release == 3 (0x10a)
932DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102)
933DREF VLR subscr MSISDN:46071 usage increases to: 4
934DREF VLR subscr MSISDN:46071 usage decreases to: 3
Philipp Maierfbf66102017-04-09 12:32:51 +0200935- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100936DREF VLR subscr MSISDN:46071 usage decreases to: 2
937DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200938DMM conn_close(vsub=MSISDN:46071, cause=0): already in release, ignore.
939DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
940 bssap_clear_sent == 1
941- BSS sends BSSMAP Clear Complete
942DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200943DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
944DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
945DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
946DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100947DREF VLR subscr MSISDN:46071 usage decreases to: 0
948DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200949DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
950DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100951 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100952===== test_reject_cm_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100953
954full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200955talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100956
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100957===== test_reject_paging_resp_during_cm
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100958---
959- Subscriber does a normal LU
960- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100961 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100962 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200963DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100964DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100965DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200966DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100967DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100968DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100969DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
970DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
971DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
972DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
973DREF VLR subscr unknown usage increases to: 1
974DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
975DVLR New subscr, IMSI: 901700000004620
976DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200977DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100978DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
979DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
980DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
981DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
982DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
983DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
984DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
985DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
986DVLR GSUP tx: 04010809710000004026f0
987GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
988DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200989DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
990DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
991DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
992DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
993DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100994 lu_result_sent == 0
995 llist_count(&net->subscr_conns) == 1
996- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
997<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
998DVLR GSUP rx 17: 10010809710000004026f00804036470f1
999DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1000DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001001DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001002DVLR GSUP tx: 12010809710000004026f0
1003GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1004DREF VLR subscr MSISDN:46071 usage decreases to: 1
1005<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1006 lu_result_sent == 0
1007- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1008<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1009DVLR GSUP rx 11: 06010809710000004026f0
1010DREF VLR subscr MSISDN:46071 usage increases to: 2
1011DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1012DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1013DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1014DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1015DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1016DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1017DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1018DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1019DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1020DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1021DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1022DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1023DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1024DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1025DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1026DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1027DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1028DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1029DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1030DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1031DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1032DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1033- sending LU Accept for MSISDN:46071
1034DREF VLR subscr MSISDN:46071 usage increases to: 3
1035DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1036DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1037DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1038DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1039DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1040DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1041DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001042DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1043DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1044DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1045DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1046DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1047DREF VLR subscr MSISDN:46071 usage increases to: 4
1048DREF VLR subscr MSISDN:46071 usage decreases to: 3
1049- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001050DREF VLR subscr MSISDN:46071 usage decreases to: 2
1051<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1052 bssap_clear_sent == 1
1053- LU was successful, and the conn has already been closed
1054 lu_result_sent == 1
1055- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001056DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1057DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1058DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001059DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001060DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1061DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1062DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1063DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1064DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001065DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001066DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001067DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1068DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001069 llist_count(&net->subscr_conns) == 0
1070---
1071- Subscriber does a normal CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001072 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001073 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001074DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001075DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001076DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001077DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001078DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001079DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1080DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1081DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1082DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1083DREF VLR subscr MSISDN:46071 usage increases to: 2
1084DREF VLR subscr MSISDN:46071 usage increases to: 3
1085DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1086DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1087DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1088DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1089DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1090DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1091DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1092DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1093DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1094DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1095- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001096DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001097DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001098DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001099DMM Subscr_Conn(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 +01001100DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001101DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1102DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
1103DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001104 cm_service_result_sent == 1
1105msc_subscr_conn_is_accepted() == true
1106---
1107- An erratic Paging Response on the same conn is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001108 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001109DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001110DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001111DMM Ignoring Paging Response, conn already established
1112DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001113 llist_count(&net->subscr_conns) == 1
1114---
1115- The original CM Service Request can conclude
1116- a USSD request is serviced
1117 expecting USSD:
1118 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +01001119 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001120DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Harald Welte80315ef2018-01-24 22:53:00 +01001121DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
1122DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001123DREF MSISDN:46071: MSC conn use - cm_service == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001124DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1125DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001126DMM USSD: Own number requested
1127DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001128DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001129- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001130- DTAP matches expected message
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001131DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
1132DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1133DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
1134DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1135DREF VLR subscr MSISDN:46071 usage increases to: 3
1136DREF VLR subscr MSISDN:46071 usage decreases to: 2
1137- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001138 bssap_clear_sent == 1
1139- all requests serviced, conn has been released
1140- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001141DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1142DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1143DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001144DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001145DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1146DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1147DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1148DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001149DRLL MSISDN:46071: Freeing subscriber connection
1150DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001151DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1152DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001153 llist_count(&net->subscr_conns) == 0
1154DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001155===== test_reject_paging_resp_during_cm: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001156
1157full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001158talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001159
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001160===== test_reject_lu_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001161---
1162- Subscriber does a normal LU
1163- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001164 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001165 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001166DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001167DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001168DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001169DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001170DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001171DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001172DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1173DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1174DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1175DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1176DREF VLR subscr unknown usage increases to: 1
1177DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1178DVLR New subscr, IMSI: 901700000004620
1179DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001180DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001181DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1182DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1183DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1184DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1185DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1186DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1187DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1188DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1189DVLR GSUP tx: 04010809710000004026f0
1190GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1191DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001192DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1193DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1194DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1195DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1196DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001197 lu_result_sent == 0
1198 llist_count(&net->subscr_conns) == 1
1199- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1200<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1201DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1202DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1203DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001204DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001205DVLR GSUP tx: 12010809710000004026f0
1206GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1207DREF VLR subscr MSISDN:46071 usage decreases to: 1
1208<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1209 lu_result_sent == 0
1210- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1211<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1212DVLR GSUP rx 11: 06010809710000004026f0
1213DREF VLR subscr MSISDN:46071 usage increases to: 2
1214DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1215DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1216DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1217DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1218DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1219DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1220DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1221DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1222DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1223DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1224DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1225DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1226DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1227DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1228DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1229DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1230DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1231DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1232DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1233DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1234DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1235DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1236- sending LU Accept for MSISDN:46071
1237DREF VLR subscr MSISDN:46071 usage increases to: 3
1238DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1239DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1240DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1241DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1242DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1243DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1244DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001245DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1246DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1247DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1248DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1249DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1250DREF VLR subscr MSISDN:46071 usage increases to: 4
1251DREF VLR subscr MSISDN:46071 usage decreases to: 3
1252- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001253DREF VLR subscr MSISDN:46071 usage decreases to: 2
1254<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1255 bssap_clear_sent == 1
1256- LU was successful, and the conn has already been closed
1257 lu_result_sent == 1
1258- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001259DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1260DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1261DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001262DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001263DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1264DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1265DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1266DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1267DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001268DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001269DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001270DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1271DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001272 llist_count(&net->subscr_conns) == 0
1273---
1274- an SMS is sent, MS is paged
1275DREF VLR subscr MSISDN:46071 usage increases to: 2
1276 llist_count(&vsub->cs.requests) == 0
1277DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001278DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001279 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001280 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001281DREF VLR subscr MSISDN:46071 usage increases to: 4
1282 llist_count(&vsub->cs.requests) == 1
1283DREF VLR subscr MSISDN:46071 usage decreases to: 3
1284 paging_sent == 1
1285 paging_stopped == 0
1286- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001287 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001288 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001289DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001290DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001291DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001292DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001293DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001294DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1295DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1296DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1297DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1298DREF VLR subscr MSISDN:46071 usage increases to: 4
1299DREF VLR subscr MSISDN:46071 usage increases to: 5
1300DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1301DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1302DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1303DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1304DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1305DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1306DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1307DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1308DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1309DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001310DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001311DPAG Paging success for MSISDN:46071 (event=0)
1312DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01001313DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001314DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001315DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001316DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001317- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001318- DTAP matches expected message
1319DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001320DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1321DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001322DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001323DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1324DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
1325DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001326 dtap_tx_confirmed == 1
1327 paging_stopped == 1
1328- conn is still open to wait for SMS ack dance
1329 llist_count(&net->subscr_conns) == 1
1330---
1331- MS sends erratic LU Request, which is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001332 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001333DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001334DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001335DMM Cannot accept another LU, conn already established; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
1336DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001337 lu_result_sent == 0
1338 llist_count(&net->subscr_conns) == 1
1339- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +01001340 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001341DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +01001342DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001343DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1344DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001345DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001346 llist_count(&net->subscr_conns) == 1
1347- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +01001348 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001349DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +01001350DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001351DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1352DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001353- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001354- DTAP matches expected message
1355DREF VLR subscr MSISDN:46071 usage decreases to: 3
1356DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001357DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2)
1358DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
1359DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1360DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
1361DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1362DREF VLR subscr MSISDN:46071 usage increases to: 3
1363DREF VLR subscr MSISDN:46071 usage decreases to: 2
1364- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001365 dtap_tx_confirmed == 1
1366 bssap_clear_sent == 1
1367- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001368DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1369DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1370DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001371DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001372DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1373DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1374DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1375DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001376DRLL MSISDN:46071: Freeing subscriber connection
1377DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001378DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1379DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001380- SMS is done
1381 llist_count(&net->subscr_conns) == 0
1382DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001383===== test_reject_lu_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001384
1385full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001386talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001387
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001388===== test_accept_cm_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001389---
1390- Subscriber does a normal LU
1391- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001392 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001393 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001394DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001395DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001396DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001397DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001398DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001399DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001400DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1401DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1402DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1403DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1404DREF VLR subscr unknown usage increases to: 1
1405DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1406DVLR New subscr, IMSI: 901700000004620
1407DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001408DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001409DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1410DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1411DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1412DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1413DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1414DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1415DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1416DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1417DVLR GSUP tx: 04010809710000004026f0
1418GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1419DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001420DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1421DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1422DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1423DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1424DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001425 lu_result_sent == 0
1426 llist_count(&net->subscr_conns) == 1
1427- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1428<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1429DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1430DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1431DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001432DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001433DVLR GSUP tx: 12010809710000004026f0
1434GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1435DREF VLR subscr MSISDN:46071 usage decreases to: 1
1436<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1437 lu_result_sent == 0
1438- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1439<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1440DVLR GSUP rx 11: 06010809710000004026f0
1441DREF VLR subscr MSISDN:46071 usage increases to: 2
1442DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1443DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1444DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1445DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1446DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1447DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1448DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1449DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1450DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1451DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1452DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1453DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1454DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1455DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1456DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1457DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1458DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1459DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1460DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1461DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1462DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1463DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1464- sending LU Accept for MSISDN:46071
1465DREF VLR subscr MSISDN:46071 usage increases to: 3
1466DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1467DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1468DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1469DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1470DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1471DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1472DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001473DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1474DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1475DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1476DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1477DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1478DREF VLR subscr MSISDN:46071 usage increases to: 4
1479DREF VLR subscr MSISDN:46071 usage decreases to: 3
1480- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001481DREF VLR subscr MSISDN:46071 usage decreases to: 2
1482<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1483 bssap_clear_sent == 1
1484- LU was successful, and the conn has already been closed
1485 lu_result_sent == 1
1486- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001487DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1488DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1489DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001490DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001491DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1492DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1493DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1494DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1495DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001496DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001497DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001498DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1499DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001500 llist_count(&net->subscr_conns) == 0
1501---
1502- an SMS is sent, MS is paged
1503DREF VLR subscr MSISDN:46071 usage increases to: 2
1504 llist_count(&vsub->cs.requests) == 0
1505DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001506DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001507 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001508 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001509DREF VLR subscr MSISDN:46071 usage increases to: 4
1510 llist_count(&vsub->cs.requests) == 1
1511DREF VLR subscr MSISDN:46071 usage decreases to: 3
1512 paging_sent == 1
1513 paging_stopped == 0
1514- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001515 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001516 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001517DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001518DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001519DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001520DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001521DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001522DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1523DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1524DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1525DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1526DREF VLR subscr MSISDN:46071 usage increases to: 4
1527DREF VLR subscr MSISDN:46071 usage increases to: 5
1528DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1529DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1530DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1531DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1532DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1533DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1534DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1535DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1536DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1537DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001538DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001539DPAG Paging success for MSISDN:46071 (event=0)
1540DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01001541DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001542DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001543DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001544DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001545- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001546- DTAP matches expected message
1547DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001548DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1549DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001550DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001551DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1552DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
1553DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001554 dtap_tx_confirmed == 1
1555 paging_stopped == 1
1556- conn is still open to wait for SMS ack dance
1557 llist_count(&net->subscr_conns) == 1
1558---
1559- CM Service Request during open connection is accepted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001560 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001561DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001562DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001563DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
1564DMM MSISDN:46071: re-using already accepted connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001565DREF MSISDN:46071: MSC conn use + cm_service == 3 (0x2a)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001566DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001567- sending CM Service Accept for MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001568DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001569 cm_service_result_sent == 1
1570 llist_count(&net->subscr_conns) == 1
1571 g_conn->received_cm_service_request == 1
1572- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +01001573 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001574DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a)
Harald Welte80315ef2018-01-24 22:53:00 +01001575DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001576DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1577DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001578DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001579 llist_count(&net->subscr_conns) == 1
1580- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +01001581 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001582DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a)
Harald Welte80315ef2018-01-24 22:53:00 +01001583DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001584DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1585DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001586- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001587- DTAP matches expected message
1588DREF VLR subscr MSISDN:46071 usage decreases to: 3
1589DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001590DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0xa)
1591DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001592 dtap_tx_confirmed == 1
1593- SMS is done
1594 llist_count(&net->subscr_conns) == 1
1595---
1596- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001597 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001598DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001599DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001600DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1601DREF VLR subscr MSISDN:46071 usage increases to: 3
1602DMM IMSI DETACH for MSISDN:46071
1603DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_ERROR)
1604DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1605DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1606DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001607DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001608DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
1609DREF MSISDN:46071: MSC conn use + release == 3 (0x10a)
1610DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102)
1611DREF VLR subscr MSISDN:46071 usage increases to: 4
1612DREF VLR subscr MSISDN:46071 usage decreases to: 3
Philipp Maierfbf66102017-04-09 12:32:51 +02001613- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001614DREF VLR subscr MSISDN:46071 usage decreases to: 2
1615DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001616DMM conn_close(vsub=MSISDN:46071, cause=0): already in release, ignore.
1617DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
1618 bssap_clear_sent == 1
1619- BSS sends BSSMAP Clear Complete
1620DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001621DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1622DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1623DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1624DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001625DREF VLR subscr MSISDN:46071 usage decreases to: 0
1626DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001627DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1628DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001629 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001630===== test_accept_cm_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001631
1632full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001633talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001634
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001635===== test_reject_paging_resp_during_paging_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001636---
1637- Subscriber does a normal LU
1638- Location Update Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001639 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001640 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001641DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001642DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001643DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001644DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001645DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001646DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001647DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1648DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1649DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1650DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1651DREF VLR subscr unknown usage increases to: 1
1652DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1653DVLR New subscr, IMSI: 901700000004620
1654DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001655DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001656DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1657DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1658DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1659DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1660DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1661DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1662DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1663DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1664DVLR GSUP tx: 04010809710000004026f0
1665GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1666DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001667DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1668DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1669DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1670DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1671DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001672 lu_result_sent == 0
1673 llist_count(&net->subscr_conns) == 1
1674- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1675<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1676DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1677DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1678DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001679DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001680DVLR GSUP tx: 12010809710000004026f0
1681GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1682DREF VLR subscr MSISDN:46071 usage decreases to: 1
1683<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1684 lu_result_sent == 0
1685- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1686<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1687DVLR GSUP rx 11: 06010809710000004026f0
1688DREF VLR subscr MSISDN:46071 usage increases to: 2
1689DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1690DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1691DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1692DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1693DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1694DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1695DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1696DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1697DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1698DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1699DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1700DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1701DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1702DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1703DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1704DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1705DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1706DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1707DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1708DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1709DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1710DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1711- sending LU Accept for MSISDN:46071
1712DREF VLR subscr MSISDN:46071 usage increases to: 3
1713DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1714DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1715DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1716DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1717DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1718DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1719DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001720DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1721DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1722DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1723DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1724DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1725DREF VLR subscr MSISDN:46071 usage increases to: 4
1726DREF VLR subscr MSISDN:46071 usage decreases to: 3
1727- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001728DREF VLR subscr MSISDN:46071 usage decreases to: 2
1729<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1730 bssap_clear_sent == 1
1731- LU was successful, and the conn has already been closed
1732 lu_result_sent == 1
1733- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001734DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1735DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1736DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001737DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001738DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1739DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1740DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1741DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1742DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001743DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001744DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001745DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1746DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001747 llist_count(&net->subscr_conns) == 0
1748---
1749- an SMS is sent, MS is paged
1750DREF VLR subscr MSISDN:46071 usage increases to: 2
1751 llist_count(&vsub->cs.requests) == 0
1752DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001753DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001754 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001755 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001756DREF VLR subscr MSISDN:46071 usage increases to: 4
1757 llist_count(&vsub->cs.requests) == 1
1758DREF VLR subscr MSISDN:46071 usage decreases to: 3
1759 paging_sent == 1
1760 paging_stopped == 0
1761- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001762 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001763 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001764DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001765DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001766DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001767DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001768DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001769DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1770DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1771DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1772DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1773DREF VLR subscr MSISDN:46071 usage increases to: 4
1774DREF VLR subscr MSISDN:46071 usage increases to: 5
1775DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1776DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1777DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1778DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1779DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1780DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1781DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1782DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1783DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1784DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001785DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001786DPAG Paging success for MSISDN:46071 (event=0)
1787DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01001788DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001789DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001790DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001791DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001792- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001793- DTAP matches expected message
1794DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001795DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1796DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001797DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001798DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1799DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
1800DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001801 dtap_tx_confirmed == 1
1802 paging_stopped == 1
1803- conn is still open to wait for SMS ack dance
1804 llist_count(&net->subscr_conns) == 1
1805---
1806- MS sends another erratic Paging Response which is dropped silently
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001807 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001808DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001809DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001810DMM Ignoring Paging Response, conn already established
1811DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001812- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +01001813 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001814DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +01001815DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001816DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1817DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001818DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001819 llist_count(&net->subscr_conns) == 1
1820- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +01001821 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001822DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +01001823DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001824DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1825DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001826- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001827- DTAP matches expected message
1828DREF VLR subscr MSISDN:46071 usage decreases to: 3
1829DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001830DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2)
1831DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
1832DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1833DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
1834DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1835DREF VLR subscr MSISDN:46071 usage increases to: 3
1836DREF VLR subscr MSISDN:46071 usage decreases to: 2
1837- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001838 dtap_tx_confirmed == 1
1839 bssap_clear_sent == 1
1840- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001841DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1842DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1843DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001844DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001845DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1846DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1847DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1848DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001849DRLL MSISDN:46071: Freeing subscriber connection
1850DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001851DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1852DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001853- SMS is done
1854 llist_count(&net->subscr_conns) == 0
1855DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001856===== test_reject_paging_resp_during_paging_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001857
1858full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001859talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001860
1861full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001862talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001863