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