Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 2a5cd93d8fe22441e9988fb10e9df2cf44a97447 / . / tests / msc_vlr / msc_vlr_test_no_authen.err
blob: c71f04aba60ed358e90790bc0cb7f028c77b3175 [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2talloc_total_blocks(tall_bsc_ctx) == 12
3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]4===== test_no_authen
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]5- Location Update request causes a GSUP LU request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]6 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]7 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]8DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]9DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]10DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]11DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
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 Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]14DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
15DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
16DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
17DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
18DREF VLR subscr unknown usage increases to: 1
19DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
20DVLR New subscr, IMSI: 901700000004620
21DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]22DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]23DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
24DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
25DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
26DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
27DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
28DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
29DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
30DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
31DVLR GSUP tx: 04010809710000004026f0
32GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
33DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]34DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
35DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
36DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
37DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
38DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]39 lu_result_sent == 0
40- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
41<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
42DVLR GSUP rx 17: 10010809710000004026f00804036470f1
43DREF VLR subscr IMSI:901700000004620 usage increases to: 2
44DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]45DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]46DVLR GSUP tx: 12010809710000004026f0
47GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
48DREF VLR subscr MSISDN:46071 usage decreases to: 1
49<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
50 lu_result_sent == 0
51- having received subscriber data does not mean acceptance
52msc_subscr_conn_is_accepted() == false
53 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]54DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
55DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
56DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
57DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
58DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
59DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]60DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
61DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]62 lu_result_sent == 0
63- HLR also sends GSUP _UPDATE_LOCATION_RESULT
64<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
65DVLR GSUP rx 11: 06010809710000004026f0
66DREF VLR subscr MSISDN:46071 usage increases to: 2
67DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
68DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
69DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
70DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
71DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
72DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
73DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
74DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
75DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
76DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
77DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
78DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
79DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
80DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
81DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
82DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
83DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
84DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
85DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
86DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
87DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
88DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
89- sending LU Accept for MSISDN:46071
90DREF VLR subscr MSISDN:46071 usage increases to: 3
91DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
92DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
93DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
94DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
95DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
96DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
97DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]98DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
99DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
100DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
101DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
102DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
103DREF VLR subscr MSISDN:46071 usage increases to: 4
104DREF VLR subscr MSISDN:46071 usage decreases to: 3
105- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]106DREF VLR subscr MSISDN:46071 usage decreases to: 2
107<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
108- LU was successful, and the conn has already been closed
109 lu_result_sent == 1
110 bssap_clear_sent == 1
111- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]112DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
113DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
114DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]115DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]116DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
117DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
118DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
119DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
120DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]121DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]122DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]123DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
124DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]125 llist_count(&net->subscr_conns) == 0
126---
127- after a while, a new conn sends a CM Service Request
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]128 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]129 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]130DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]131DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]132DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]133DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]134DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]135DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
136DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
137DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
138DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
139DREF VLR subscr MSISDN:46071 usage increases to: 2
140DREF VLR subscr MSISDN:46071 usage increases to: 3
141DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
142DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
143DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
144DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
145DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
146DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
147DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
148DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
149DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
150DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
151- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]152DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]153DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]154DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]155DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]156DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]157DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
158DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
159DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]160 cm_service_result_sent == 1
161msc_subscr_conn_is_accepted() == true
162- a USSD request is serviced
163 expecting USSD:
164 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]165 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]166DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]167DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
168DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]169DREF MSISDN:46071: MSC conn use - cm_service == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]170DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
171DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]172DMM USSD: Own number requested
173DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]174DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]175- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]176- DTAP matches expected message
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]177DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
178DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
179DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
180DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
181DREF VLR subscr MSISDN:46071 usage increases to: 3
182DREF VLR subscr MSISDN:46071 usage decreases to: 2
183- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]184 dtap_tx_confirmed == 1
185 bssap_clear_sent == 1
186- all requests serviced, conn has been released
187- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]188DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
189DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
190DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]191DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]192DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
193DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
194DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
195DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]196DRLL MSISDN:46071: Freeing subscriber connection
197DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]198DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
199DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]200 llist_count(&net->subscr_conns) == 0
201---
202- an SMS is sent, MS is paged
203DREF VLR subscr MSISDN:46071 usage increases to: 2
204 llist_count(&vsub->cs.requests) == 0
205DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]206DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]207 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]208 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]209DREF VLR subscr MSISDN:46071 usage increases to: 4
210 llist_count(&vsub->cs.requests) == 1
211DREF VLR subscr MSISDN:46071 usage decreases to: 3
212 paging_sent == 1
213 paging_stopped == 0
214- the subscriber and its pending request should remain
215DREF VLR subscr MSISDN:46071 usage increases to: 4
216 llist_count(&vsub->cs.requests) == 1
217DREF VLR subscr MSISDN:46071 usage decreases to: 3
218- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]219 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]220 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]221DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]222DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]223DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]224DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]225DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]226DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
227DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
228DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
229DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
230DREF VLR subscr MSISDN:46071 usage increases to: 4
231DREF VLR subscr MSISDN:46071 usage increases to: 5
232DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
233DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
234DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
235DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
236DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
237DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
238DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
239DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
240DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
241DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]242DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]243DPAG Paging success for MSISDN:46071 (event=0)
244DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]245DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]246DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]247DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]248DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]249- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]250- DTAP matches expected message
251DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]252DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
253DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]254DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]255DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
256DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
257DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]258 dtap_tx_confirmed == 1
259 paging_stopped == 1
260- SMS was delivered, no requests pending for subscr
261DREF VLR subscr MSISDN:46071 usage increases to: 5
262 llist_count(&vsub->cs.requests) == 0
263DREF VLR subscr MSISDN:46071 usage decreases to: 4
264- conn is still open to wait for SMS ack dance
265 llist_count(&net->subscr_conns) == 1
266- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]267 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]268DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]269DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]270DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
271DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]272DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]273 llist_count(&net->subscr_conns) == 1
274- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]275 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]276DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]277DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]278DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
279DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]280- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]281- DTAP matches expected message
282DREF VLR subscr MSISDN:46071 usage decreases to: 3
283DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]284DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2)
285DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
286DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
287DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
288DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
289DREF VLR subscr MSISDN:46071 usage increases to: 3
290DREF VLR subscr MSISDN:46071 usage decreases to: 2
291- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]292 dtap_tx_confirmed == 1
293 bssap_clear_sent == 1
294- SMS is done, conn is gone
295- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]296DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
297DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
298DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]299DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]300DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
301DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
302DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
303DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]304DRLL MSISDN:46071: Freeing subscriber connection
305DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]306DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
307DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]308 llist_count(&net->subscr_conns) == 0
309---
310- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]311 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]312 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]313DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]314DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]315DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]316DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
317DREF VLR subscr MSISDN:46071 usage increases to: 2
318DMM IMSI DETACH for MSISDN:46071
319DREF VLR subscr MSISDN:46071 usage decreases to: 1
320DREF VLR subscr MSISDN:46071 usage decreases to: 0
321DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]322DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
323DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
324DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
325DREF unknown: MSC conn use + release == 2 (0x101)
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]326- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]327DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
328 bssap_clear_sent == 1
329- BSS sends BSSMAP Clear Complete
330DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]331DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
332DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
333DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]334DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]335DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
336DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]337 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]338===== test_no_authen: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]339
340full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]341talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]343===== test_no_authen_tmsi
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]344- Location Update request causes a GSUP LU request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]345 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]346 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]347DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]348DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]349DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]350DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]351DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]352DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]353DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
354DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
355DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
356DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
357DREF VLR subscr unknown usage increases to: 1
358DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
359DVLR New subscr, IMSI: 901700000004620
360DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]361DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]362DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
363DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
364DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
365DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
366DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
367DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
368DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
369DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
370DVLR GSUP tx: 04010809710000004026f0
371GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
372DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]373DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
374DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
375DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
376DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
377DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]378 lu_result_sent == 0
379- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
380<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
381DVLR GSUP rx 17: 10010809710000004026f00804036470f1
382DREF VLR subscr IMSI:901700000004620 usage increases to: 2
383DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]384DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]385DVLR GSUP tx: 12010809710000004026f0
386GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
387DREF VLR subscr MSISDN:46071 usage decreases to: 1
388<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
389 lu_result_sent == 0
390- having received subscriber data does not mean acceptance
391msc_subscr_conn_is_accepted() == false
392 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]393DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
394DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
395DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
396DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
397DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
398DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]399DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
400DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]401 lu_result_sent == 0
402- HLR also sends GSUP _UPDATE_LOCATION_RESULT
403<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
404DVLR GSUP rx 11: 06010809710000004026f0
405DREF VLR subscr MSISDN:46071 usage increases to: 2
406DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
407DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
408DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
409DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
410DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
411DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
412DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
413DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
414DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
415DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
416DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
417DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
418DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
419DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
420DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
421DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
422DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
423DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
424DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
425DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
426DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
427DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
428DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
429DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
430- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
431DREF VLR subscr MSISDN:46071 usage decreases to: 1
432<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
433- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
434 llist_count(&net->subscr_conns) == 1
435 lu_result_sent == 1
436msc_subscr_conn_is_accepted() == false
437 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]438DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
439DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
440DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
441DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
442DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
443DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]444DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
445DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]446- even though the TMSI is not acked, we can already find the subscr with it
447DREF VLR subscr MSISDN:46071 usage increases to: 2
448 vsub != NULL == 1
449 strcmp(vsub->imsi, imsi) == 0
450 vsub->tmsi_new == 0x03020100
451 vsub->tmsi == 0xffffffff
452DREF VLR subscr MSISDN:46071 usage decreases to: 1
453- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]454 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]455DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]456DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]457DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
458DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
459DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
460DREF VLR subscr MSISDN:46071 usage increases to: 2
461DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
462DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
463DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
464DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
465DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
466DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
467DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]468DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
469DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
470DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
471DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
472DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
473DREF VLR subscr MSISDN:46071 usage increases to: 3
474DREF VLR subscr MSISDN:46071 usage decreases to: 2
475- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]476DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
477 bssap_clear_sent == 1
478- LU was successful, and the conn has already been closed
479- BSS sends BSSMAP Clear Complete
480DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]481DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
482DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]483DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]484DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
485DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
486DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
487DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
488DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]489DRLL MSISDN:46071: Freeing subscriber connection
490DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]491DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
492DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]493 llist_count(&net->subscr_conns) == 0
494- Subscriber has the new TMSI
495DREF VLR subscr MSISDN:46071 usage increases to: 2
496 vsub != NULL == 1
497 strcmp(vsub->imsi, imsi) == 0
498 vsub->tmsi_new == 0xffffffff
499 vsub->tmsi == 0x03020100
500DREF VLR subscr MSISDN:46071 usage decreases to: 1
501---
502- after a while, a new conn sends a CM Service Request using above TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]503 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]504 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]505DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]506DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]507DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]508DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]509DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]510DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
511DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
512DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
513DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
514DREF VLR subscr MSISDN:46071 usage increases to: 2
515DREF VLR subscr MSISDN:46071 usage increases to: 3
516DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
517DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
518DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
519DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
520DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
521DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
522DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
523DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
524DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
525DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
526- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]527DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]528DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]529DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]530DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]531DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]532DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
533DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
534DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]535 cm_service_result_sent == 1
536msc_subscr_conn_is_accepted() == true
537- a USSD request is serviced
538 expecting USSD:
539 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]540 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]541DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]542DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
543DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]544DREF MSISDN:46071: MSC conn use - cm_service == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]545DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
546DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]547DMM USSD: Own number requested
548DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]549DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]550- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]551- DTAP matches expected message
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]552DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
553DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
554DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
555DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
556DREF VLR subscr MSISDN:46071 usage increases to: 3
557DREF VLR subscr MSISDN:46071 usage decreases to: 2
558- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]559 bssap_clear_sent == 1
560- all requests serviced, conn has been released
561- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]562DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
563DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
564DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]565DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]566DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
567DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
568DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
569DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]570DRLL MSISDN:46071: Freeing subscriber connection
571DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]572DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
573DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]574 llist_count(&net->subscr_conns) == 0
575---
576- an SMS is sent, MS is paged using above TMSI
577DREF VLR subscr MSISDN:46071 usage increases to: 2
578 llist_count(&vsub->cs.requests) == 0
579DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]580DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]581 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]582 paging_expecting_tmsi == 0x03020100
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]583DREF VLR subscr MSISDN:46071 usage increases to: 4
584 llist_count(&vsub->cs.requests) == 1
585DREF VLR subscr MSISDN:46071 usage decreases to: 3
586 paging_sent == 1
587 paging_stopped == 0
588- the subscriber and its pending request should remain
589DREF VLR subscr MSISDN:46071 usage increases to: 4
590 llist_count(&vsub->cs.requests) == 1
591DREF VLR subscr MSISDN:46071 usage decreases to: 3
592- MS replies with Paging Response using TMSI, we deliver the SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]593 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]594 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]595DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]596DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]597DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]598DRR PAGING RESPONSE: MI(TMSI)=50462976
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]599DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]600DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
601DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
602DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
603DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
604DREF VLR subscr MSISDN:46071 usage increases to: 4
605DREF VLR subscr MSISDN:46071 usage increases to: 5
606DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
607DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
608DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
609DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
610DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
611DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
612DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
613DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
614DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
615DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]616DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]617DPAG Paging success for MSISDN:46071 (event=0)
618DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]619DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]620DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]621DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]622DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]623- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]624- DTAP matches expected message
625DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]626DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
627DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]628DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]629DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
630DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted
631DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]632 dtap_tx_confirmed == 1
633 paging_stopped == 1
634- SMS was delivered, no requests pending for subscr
635DREF VLR subscr MSISDN:46071 usage increases to: 5
636 llist_count(&vsub->cs.requests) == 0
637DREF VLR subscr MSISDN:46071 usage decreases to: 4
638- conn is still open to wait for SMS ack dance
639 llist_count(&net->subscr_conns) == 1
640- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]641 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]642DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]643DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]644DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
645DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]646DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]647 llist_count(&net->subscr_conns) == 1
648- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]649 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]650DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22)
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]651DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]652DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
653DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]654- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]655- DTAP matches expected message
656DREF VLR subscr MSISDN:46071 usage decreases to: 3
657DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]658DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2)
659DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
660DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
661DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
662DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
663DREF VLR subscr MSISDN:46071 usage increases to: 3
664DREF VLR subscr MSISDN:46071 usage decreases to: 2
665- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]666 dtap_tx_confirmed == 1
667 bssap_clear_sent == 1
668- SMS is done, conn is gone
669- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]670DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
671DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
672DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]673DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]674DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
675DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
676DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
677DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]678DRLL MSISDN:46071: Freeing subscriber connection
679DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]680DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
681DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]682 llist_count(&net->subscr_conns) == 0
683---
684- subscriber sends LU Request, this time with the TMSI
685- Location Update request causes a GSUP LU request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]686 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]687 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]688DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]689DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]690DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]691DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]692DMM LOCATION UPDATING REQUEST: MI(TMSI)=50462976 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]693DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]694DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Allocated
695DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: is child of Subscr_Conn(50462976)
696DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
697DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
698DREF VLR subscr MSISDN:46071 usage increases to: 2
699DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]700DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]701DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
702DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
703DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
704DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
705DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
706DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Allocated
707DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
708DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
709DVLR GSUP tx: 04010809710000004026f0
710GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
711DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]712DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
713DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
714DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0)
715DMM Subscr_Conn(50462976){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
716DMM Subscr_Conn(50462976){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]717 lu_result_sent == 0
718- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
719<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
720DVLR GSUP rx 17: 10010809710000004026f00804036470f1
721DREF VLR subscr MSISDN:46071 usage increases to: 3
722DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]723DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]724DVLR GSUP tx: 12010809710000004026f0
725GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
726DREF VLR subscr MSISDN:46071 usage decreases to: 2
727<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
728 lu_result_sent == 0
729- having received subscriber data does not mean acceptance
730msc_subscr_conn_is_accepted() == false
731 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]732DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
733DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
734DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
735DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
736DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
737DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]738DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
739DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]740 lu_result_sent == 0
741- HLR also sends GSUP _UPDATE_LOCATION_RESULT
742<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
743DVLR GSUP rx 11: 06010809710000004026f0
744DREF VLR subscr MSISDN:46071 usage increases to: 3
745DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
746DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
747DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
748DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
749DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
750DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Freeing instance
751DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Deallocated
752DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
753DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
754DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Allocated
755DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
756DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
757DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
758DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Allocated
759DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(50462976)
760DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
761DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
762DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
763DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(50462976)
764DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Freeing instance
765DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Deallocated
766DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
767DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
768DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
769- sending LU Accept for MSISDN:46071, with TMSI 0x07060504
770DREF VLR subscr MSISDN:46071 usage decreases to: 2
771<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
772- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
773 llist_count(&net->subscr_conns) == 1
774 lu_result_sent == 1
775msc_subscr_conn_is_accepted() == false
776 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]777DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
778DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
779DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
780DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
781DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
782DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]783DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
784DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]785- even though the TMSI is not acked, we can already find the subscr with it
786DREF VLR subscr MSISDN:46071 usage increases to: 3
787 vsub != NULL == 1
788 strcmp(vsub->imsi, imsi) == 0
789 vsub->tmsi_new == 0x07060504
790 vsub->tmsi == 0x03020100
791DREF VLR subscr MSISDN:46071 usage decreases to: 2
792- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]793 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]794DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]795DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]796DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
797DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
798DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
799DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
800DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
801DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
802DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
803DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Freeing instance
804DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Deallocated
805DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]806DMM Subscr_Conn(50462976){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
807DMM Subscr_Conn(50462976){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
808DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
809DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
810DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
811DREF VLR subscr MSISDN:46071 usage increases to: 3
812DREF VLR subscr MSISDN:46071 usage decreases to: 2
813- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]814DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
815 bssap_clear_sent == 1
816- LU was successful, and the conn has already been closed
817- BSS sends BSSMAP Clear Complete
818DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]819DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
820DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]821DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]822DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
823DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(50462976)
824DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
825DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Freeing instance
826DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]827DRLL MSISDN:46071: Freeing subscriber connection
828DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]829DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
830DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]831 llist_count(&net->subscr_conns) == 0
832- subscriber has the new TMSI
833DREF VLR subscr MSISDN:46071 usage increases to: 2
834 vsub != NULL == 1
835 strcmp(vsub->imsi, imsi) == 0
836 vsub->tmsi_new == 0xffffffff
837 vsub->tmsi == 0x07060504
838DREF VLR subscr MSISDN:46071 usage decreases to: 1
839---
840- subscriber detaches, using new TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]841 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]842 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]843DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]844DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]845DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]846DMM IMSI DETACH INDICATION: MI(TMSI)=117835012
847DREF VLR subscr MSISDN:46071 usage increases to: 2
848DMM IMSI DETACH for MSISDN:46071
849DREF VLR subscr MSISDN:46071 usage decreases to: 1
850DREF VLR subscr MSISDN:46071 usage decreases to: 0
851DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]852DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
853DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
854DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
855DREF unknown: MSC conn use + release == 2 (0x101)
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]856- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]857DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
858 bssap_clear_sent == 1
859- BSS sends BSSMAP Clear Complete
860DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]861DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
862DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
863DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]864DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]865DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
866DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]867 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]868===== test_no_authen_tmsi: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]869
870full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]871talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]872
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]873===== test_no_authen_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]874- Location Update request causes a GSUP LU request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]875 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]876 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]877DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]878DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]879DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]880DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]881DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]882DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]883DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
884DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
885DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
886DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
887DREF VLR subscr unknown usage increases to: 1
888DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
889DVLR New subscr, IMSI: 901700000004620
890DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]891DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]892DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
893DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
894DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
895DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
896DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
897DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
898DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
899DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
900DVLR GSUP tx: 04010809710000004026f0
901GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
902DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]903DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
904DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
905DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
906DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
907DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]908 lu_result_sent == 0
909- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
910<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
911DVLR GSUP rx 17: 10010809710000004026f00804036470f1
912DREF VLR subscr IMSI:901700000004620 usage increases to: 2
913DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]914DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]915DVLR GSUP tx: 12010809710000004026f0
916GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
917DREF VLR subscr MSISDN:46071 usage decreases to: 1
918<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
919 lu_result_sent == 0
920- having received subscriber data does not mean acceptance
921msc_subscr_conn_is_accepted() == false
922 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]923DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
924DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
925DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
926DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
927DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
928DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]929DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
930DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]931 lu_result_sent == 0
932- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
933<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
934DVLR GSUP rx 11: 06010809710000004026f0
935DREF VLR subscr MSISDN:46071 usage increases to: 2
936DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
937DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
938DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
939DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
940DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
941DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
942DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
943DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
944DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
945DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
946DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
947DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
948DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
949DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
950DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
951DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
952DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
953DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
954DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
955DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
956DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
957DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
958DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]959DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]960- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]961- DTAP matches expected message
962DREF VLR subscr MSISDN:46071 usage decreases to: 1
963<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
964- We will only do business when the IMEI is known
965 llist_count(&net->subscr_conns) == 1
966DREF VLR subscr MSISDN:46071 usage increases to: 2
967 vsub->imei[0] == 0
968DREF VLR subscr MSISDN:46071 usage decreases to: 1
969msc_subscr_conn_is_accepted() == false
970 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]971DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
972DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
973DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
974DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
975DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
976DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]977DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
978DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]979- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]980 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]981DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]982DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]983DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
984DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]985DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
986DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
987- sending LU Accept for MSISDN:46071
988DREF VLR subscr MSISDN:46071 usage increases to: 2
989DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
990DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
991DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
992DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
993DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
994DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
995DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]996DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
997DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
998DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
999DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1000DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
1001DREF VLR subscr MSISDN:46071 usage increases to: 3
1002DREF VLR subscr MSISDN:46071 usage decreases to: 2
1003- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1004DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
1005 bssap_clear_sent == 1
1006- LU was successful, and the conn has already been closed
1007 lu_result_sent == 1
1008- BSS sends BSSMAP Clear Complete
1009DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1010DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1011DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1012DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1013DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1014DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1015DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1016DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1017DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1018DRLL MSISDN:46071: Freeing subscriber connection
1019DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1020DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1021DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1022 llist_count(&net->subscr_conns) == 0
1023- Subscriber has the IMEI
1024DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1025 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1026DREF VLR subscr MSISDN:46071 usage decreases to: 1
1027---
1028- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1029 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1030 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1031DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1032DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1033DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1034DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1035DREF VLR subscr MSISDN:46071 usage increases to: 2
1036DMM IMSI DETACH for MSISDN:46071
1037DREF VLR subscr MSISDN:46071 usage decreases to: 1
1038DREF VLR subscr MSISDN:46071 usage decreases to: 0
1039DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1040DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1041DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
1042DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
1043DREF unknown: MSC conn use + release == 2 (0x101)
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]1044- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1045DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
1046 bssap_clear_sent == 1
1047- BSS sends BSSMAP Clear Complete
1048DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1049DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1050DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1051DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1052DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1053DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
1054DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1055 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1056===== test_no_authen_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1057
1058full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1059talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1060
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1061===== test_no_authen_tmsi_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1062- Location Update request causes a GSUP LU request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1063 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1064 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1065DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1066DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1067DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]1068DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1069DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1070DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1071DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1072DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1073DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1074DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1075DREF VLR subscr unknown usage increases to: 1
1076DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1077DVLR New subscr, IMSI: 901700000004620
1078DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1079DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1080DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1081DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1082DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1083DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1084DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1085DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1086DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1087DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1088DVLR GSUP tx: 04010809710000004026f0
1089GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1090DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1091DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1092DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1093DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1094DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1095DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1096 lu_result_sent == 0
1097- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1098<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1099DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1100DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1101DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1102DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1103DVLR GSUP tx: 12010809710000004026f0
1104GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1105DREF VLR subscr MSISDN:46071 usage decreases to: 1
1106<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1107 lu_result_sent == 0
1108- having received subscriber data does not mean acceptance
1109msc_subscr_conn_is_accepted() == false
1110 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1111DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1112DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1113DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1114DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1115DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1116DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1117DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1118DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1119 lu_result_sent == 0
1120- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1121<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1122DVLR GSUP rx 11: 06010809710000004026f0
1123DREF VLR subscr MSISDN:46071 usage increases to: 2
1124DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1125DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1126DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1127DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1128DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1129DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1130DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1131DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1132DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1133DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1134DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1135DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1136DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1137DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1138DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1139DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1140DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1141DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1142DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1143DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1144DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1145DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1146DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI_TMSI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1147DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1148- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1149- DTAP matches expected message
1150DREF VLR subscr MSISDN:46071 usage decreases to: 1
1151<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1152- We will only do business when the IMEI is known
1153 llist_count(&net->subscr_conns) == 1
1154DREF VLR subscr MSISDN:46071 usage increases to: 2
1155 vsub->imei[0] == 0
1156DREF VLR subscr MSISDN:46071 usage decreases to: 1
1157msc_subscr_conn_is_accepted() == false
1158 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1159DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1160DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1161DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1162DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1163DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1164DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1165DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1166DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1167- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1168 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1169DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1170DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1171DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1172DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1173DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1174DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1175DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
1176DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1177- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1178DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
1179DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1180DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1181- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1182 llist_count(&net->subscr_conns) == 1
1183 lu_result_sent == 1
1184msc_subscr_conn_is_accepted() == false
1185 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1186DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1187DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1188DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1189DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1190DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1191DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1192DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1193DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1194- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1195 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1196DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1197DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1198DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1199DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1200DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1201DREF VLR subscr MSISDN:46071 usage increases to: 2
1202DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1203DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1204DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1205DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1206DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1207DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1208DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1209DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1210DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1211DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1212DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1213DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
1214DREF VLR subscr MSISDN:46071 usage increases to: 3
1215DREF VLR subscr MSISDN:46071 usage decreases to: 2
1216- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1217DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
1218 bssap_clear_sent == 1
1219- LU was successful, and the conn has already been closed
1220 lu_result_sent == 1
1221- BSS sends BSSMAP Clear Complete
1222DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1223DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1224DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1225DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1226DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1227DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1228DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1229DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1230DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1231DRLL MSISDN:46071: Freeing subscriber connection
1232DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1233DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1234DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1235 llist_count(&net->subscr_conns) == 0
1236- Subscriber has the IMEI and TMSI
1237DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1238 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1239 vsub->tmsi == 0x03020100
1240DREF VLR subscr MSISDN:46071 usage decreases to: 1
1241---
1242- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1243 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1244 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1245DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1246DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1247DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1248DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1249DREF VLR subscr MSISDN:46071 usage increases to: 2
1250DMM IMSI DETACH for MSISDN:46071
1251DREF VLR subscr MSISDN:46071 usage decreases to: 1
1252DREF VLR subscr MSISDN:46071 usage decreases to: 0
1253DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1254DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1255DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
1256DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
1257DREF unknown: MSC conn use + release == 2 (0x101)
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]1258- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1259DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
1260 bssap_clear_sent == 1
1261- BSS sends BSSMAP Clear Complete
1262DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1263DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1264DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1265DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1266DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1267DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
1268DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1269 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1270===== test_no_authen_tmsi_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1271
1272full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1273talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1274
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1275===== test_no_authen_imeisv
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1276- Location Update request causes an IMEISV ID request back to the MS
1277 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1278 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1279DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1280DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1281DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]1282DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1283DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1284DMM LU/new-LAC: 1/23
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1285DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1286DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1287DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1288DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1289DREF VLR subscr unknown usage increases to: 1
1290DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1291DVLR New subscr, IMSI: 901700000004620
1292DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1293DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1294DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A
1295- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051803
1296- DTAP matches expected message
1297DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_IMEISV
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1298DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1299DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1300DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1301DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1302DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1303- MS replies with an Identity Response, causes LU to commence with a GSUP LU request to HLR
1304 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1305DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1306DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
1307DMM IDENTITY RESPONSE: MI(IMEI-SV)=4234234234234275
1308DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=4234234234234275
1309DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: Received Event VLR_ULA_E_ID_IMEISV
1310DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node1()
1311DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_auth()
1312DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_ciph()
1313DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node_4()
1314DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1315DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1316DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1317DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1318DVLR GSUP tx: 04010809710000004026f0
1319GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1320DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1321DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
1322DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1323DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1324 lu_result_sent == 0
1325- Subscriber has the IMEISV from the ID Response
1326DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1327 strcmp(vsub->imeisv, "4234234234234275") == 0
1328DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1329- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1330<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1331DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1332DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1333DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1334DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1335DVLR GSUP tx: 12010809710000004026f0
1336GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1337DREF VLR subscr MSISDN:46071 usage decreases to: 1
1338<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1339 lu_result_sent == 0
1340- having received subscriber data does not mean acceptance
1341msc_subscr_conn_is_accepted() == false
1342 requests shall be thwarted
1343DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1344DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1345DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1346DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1347DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1348DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1349DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1350DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1351 lu_result_sent == 0
1352- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1353<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1354DVLR GSUP rx 11: 06010809710000004026f0
1355DREF VLR subscr MSISDN:46071 usage increases to: 2
1356DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1357DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1358DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1359DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1360DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1361DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1362DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1363DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1364DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1365DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1366DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1367DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1368DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1369DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1370DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1371DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1372DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1373DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1374DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1375DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1376DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1377DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1378- sending LU Accept for MSISDN:46071
1379DREF VLR subscr MSISDN:46071 usage increases to: 3
1380DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1381DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1382DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1383DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1384DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1385DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1386DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1387DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1388DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1389DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1390DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1391DREF MSISDN:46071: MSC conn use + release == 1 (0x100)
1392DREF VLR subscr MSISDN:46071 usage increases to: 4
1393DREF VLR subscr MSISDN:46071 usage decreases to: 3
1394- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1395DREF VLR subscr MSISDN:46071 usage decreases to: 2
1396<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1397- LU was successful, and the conn has already been closed
1398 lu_result_sent == 1
1399 bssap_clear_sent == 1
1400- BSS sends BSSMAP Clear Complete
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1401DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
1402DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1403DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1404DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1405DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1406DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1407DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1408DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1409DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1410DRLL MSISDN:46071: Freeing subscriber connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1411DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1412DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1413DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1414 llist_count(&net->subscr_conns) == 0
1415---
1416- subscriber detaches
1417 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
1418 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1419DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1420DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1421DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
1422DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1423DREF VLR subscr MSISDN:46071 usage increases to: 2
1424DMM IMSI DETACH for MSISDN:46071
1425DREF VLR subscr MSISDN:46071 usage decreases to: 1
1426DREF VLR subscr MSISDN:46071 usage decreases to: 0
1427DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1428DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1429DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
1430DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
1431DREF unknown: MSC conn use + release == 2 (0x101)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1432- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1433DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
1434 bssap_clear_sent == 1
1435- BSS sends BSSMAP Clear Complete
1436DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1437DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1438DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1439DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1440DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1441DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
1442DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1443 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1444===== test_no_authen_imeisv: SUCCESS
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1445
1446full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1447talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1448
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1449===== test_no_authen_imeisv_imei
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1450- Location Update request causes an IMEISV ID request back to the MS
1451 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1452 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1453DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1454DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1455DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]1456DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1457DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1458DMM LU/new-LAC: 1/23
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1459DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1460DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1461DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1462DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1463DREF VLR subscr unknown usage increases to: 1
1464DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1465DVLR New subscr, IMSI: 901700000004620
1466DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1467DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1468DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A
1469- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051803
1470- DTAP matches expected message
1471DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_IMEISV
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1472DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1473DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1474DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1475DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1476DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1477- MS replies with an Identity Response, causes LU to commence with a GSUP LU request to HLR
1478 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1479DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1480DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
1481DMM IDENTITY RESPONSE: MI(IMEI-SV)=4234234234234275
1482DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=4234234234234275
1483DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: Received Event VLR_ULA_E_ID_IMEISV
1484DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node1()
1485DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_auth()
1486DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_ciph()
1487DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node_4()
1488DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1489DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1490DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1491DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1492DVLR GSUP tx: 04010809710000004026f0
1493GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1494DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1495DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
1496DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1497DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1498 lu_result_sent == 0
1499- Subscriber has the IMEISV from the ID Response
1500DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1501 strcmp(vsub->imeisv, "4234234234234275") == 0
1502DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1503- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1504<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1505DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1506DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1507DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1508DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1509DVLR GSUP tx: 12010809710000004026f0
1510GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1511DREF VLR subscr MSISDN:46071 usage decreases to: 1
1512<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1513 lu_result_sent == 0
1514- having received subscriber data does not mean acceptance
1515msc_subscr_conn_is_accepted() == false
1516 requests shall be thwarted
1517DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1518DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1519DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1520DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1521DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1522DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1523DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1524DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1525 lu_result_sent == 0
1526- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1527<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1528DVLR GSUP rx 11: 06010809710000004026f0
1529DREF VLR subscr MSISDN:46071 usage increases to: 2
1530DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1531DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1532DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1533DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1534DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1535DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1536DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1537DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1538DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1539DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1540DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1541DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1542DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1543DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1544DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1545DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1546DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1547DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1548DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1549DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1550DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1551DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1552DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI
1553DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
1554- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
1555- DTAP matches expected message
1556DREF VLR subscr MSISDN:46071 usage decreases to: 1
1557<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1558- We will only do business when the IMEI is known
1559 llist_count(&net->subscr_conns) == 1
1560DREF VLR subscr MSISDN:46071 usage increases to: 2
1561 vsub->imei[0] == 0
1562DREF VLR subscr MSISDN:46071 usage decreases to: 1
1563msc_subscr_conn_is_accepted() == false
1564 requests shall be thwarted
1565DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1566DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1567DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1568DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1569DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1570DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1571DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1572DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1573- MS replies with an Identity Response
1574 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1575DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1576DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
1577DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1578DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
1579DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1580DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1581- sending LU Accept for MSISDN:46071
1582DREF VLR subscr MSISDN:46071 usage increases to: 2
1583DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
1584DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1585DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1586DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1587DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1588DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1589DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1590DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1591DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1592DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1593DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1594DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
1595DREF VLR subscr MSISDN:46071 usage increases to: 3
1596DREF VLR subscr MSISDN:46071 usage decreases to: 2
1597- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1598DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
1599 bssap_clear_sent == 1
1600- LU was successful, and the conn has already been closed
1601 lu_result_sent == 1
1602- BSS sends BSSMAP Clear Complete
1603DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1604DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1605DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1606DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1607DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1608DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1609DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1610DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1611DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1612DRLL MSISDN:46071: Freeing subscriber connection
1613DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1614DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1615DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1616 llist_count(&net->subscr_conns) == 0
1617- Subscriber has the IMEI
1618DREF VLR subscr MSISDN:46071 usage increases to: 2
1619 strcmp(vsub->imei, "423423423423420") == 0
1620DREF VLR subscr MSISDN:46071 usage decreases to: 1
1621---
1622- subscriber detaches
1623 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
1624 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1625DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1626DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1627DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
1628DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1629DREF VLR subscr MSISDN:46071 usage increases to: 2
1630DMM IMSI DETACH for MSISDN:46071
1631DREF VLR subscr MSISDN:46071 usage decreases to: 1
1632DREF VLR subscr MSISDN:46071 usage decreases to: 0
1633DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1634DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1635DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
1636DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
1637DREF unknown: MSC conn use + release == 2 (0x101)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1638- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1639DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
1640 bssap_clear_sent == 1
1641- BSS sends BSSMAP Clear Complete
1642DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1643DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1644DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1645DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1646DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1647DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
1648DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1649 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1650===== test_no_authen_imeisv_imei: SUCCESS
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1651
1652full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1653talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1654
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]1655===== test_no_authen_imeisv_tmsi
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1656- Location Update request causes an IMEISV ID request back to the MS
1657 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1658 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1659DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1660DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1661DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]1662DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1663DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1664DMM LU/new-LAC: 1/23
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1665DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1666DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1667DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1668DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1669DREF VLR subscr unknown usage increases to: 1
1670DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1671DVLR New subscr, IMSI: 901700000004620
1672DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1673DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1674DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A
1675- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051803
1676- DTAP matches expected message
1677DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_IMEISV
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1678DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1679DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1680DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
1681DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1682DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1683- MS replies with an Identity Response, causes LU to commence with a GSUP LU request to HLR
1684 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1685DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1686DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
1687DMM IDENTITY RESPONSE: MI(IMEI-SV)=4234234234234275
1688DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=4234234234234275
1689DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: Received Event VLR_ULA_E_ID_IMEISV
1690DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node1()
1691DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_auth()
1692DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_ciph()
1693DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node_4()
1694DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1695DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1696DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1697DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1698DVLR GSUP tx: 04010809710000004026f0
1699GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1700DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1701DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
1702DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1703DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1704 lu_result_sent == 0
1705- Subscriber has the IMEISV from the ID Response
1706DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1707 strcmp(vsub->imeisv, "4234234234234275") == 0
1708DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1709- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1710<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1711DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1712DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1713DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1714DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1715DVLR GSUP tx: 12010809710000004026f0
1716GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1717DREF VLR subscr MSISDN:46071 usage decreases to: 1
1718<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1719 lu_result_sent == 0
1720- having received subscriber data does not mean acceptance
1721msc_subscr_conn_is_accepted() == false
1722 requests shall be thwarted
1723DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1724DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1725DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1726DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1727DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1728DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1729DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1730DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1731 lu_result_sent == 0
1732- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1733<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1734DVLR GSUP rx 11: 06010809710000004026f0
1735DREF VLR subscr MSISDN:46071 usage increases to: 2
1736DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1737DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1738DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1739DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1740DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1741DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1742DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1743DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1744DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1745DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1746DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1747DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1748DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1749DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1750DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1751DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1752DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1753DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1754DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1755DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1756DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1757DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1758DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1759DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1760- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
1761DREF VLR subscr MSISDN:46071 usage decreases to: 1
1762<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1763- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1764 llist_count(&net->subscr_conns) == 1
1765 lu_result_sent == 1
1766msc_subscr_conn_is_accepted() == false
1767 requests shall be thwarted
1768DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1769DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1770DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1771DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1772DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1773DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1774DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1775DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1776- even though the TMSI is not acked, we can already find the subscr with it
1777DREF VLR subscr MSISDN:46071 usage increases to: 2
1778 vsub != NULL == 1
1779 strcmp(vsub->imsi, imsi) == 0
1780 vsub->tmsi_new == 0x03020100
1781 vsub->tmsi == 0xffffffff
1782DREF VLR subscr MSISDN:46071 usage decreases to: 1
1783- MS sends TMSI Realloc Complete
1784 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1785DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1786DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1787DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1788DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1789DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1790DREF VLR subscr MSISDN:46071 usage increases to: 2
1791DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1792DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1793DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1794DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1795DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1796DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1797DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1798DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1799DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1800DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1801DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1802DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
1803DREF VLR subscr MSISDN:46071 usage increases to: 3
1804DREF VLR subscr MSISDN:46071 usage decreases to: 2
1805- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1806DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
1807 bssap_clear_sent == 1
1808- LU was successful, and the conn has already been closed
1809- BSS sends BSSMAP Clear Complete
1810DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1811DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1812DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1813DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1814DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1815DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1816DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1817DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1818DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1819DRLL MSISDN:46071: Freeing subscriber connection
1820DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1821DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1822DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1823 llist_count(&net->subscr_conns) == 0
1824---
1825- subscriber sends LU Request, this time with the TMSI
1826- Location Update request causes an IMEISV ID request back to the MS
1827 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1828 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1829DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1830DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1831DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]1832DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1833DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1834DMM LU/new-LAC: 1/23
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1835DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1836DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1837DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1838DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1839DREF VLR subscr MSISDN:46071 usage increases to: 2
1840DREF VLR subscr MSISDN:46071 usage increases to: 3
1841DREF VLR subscr MSISDN:46071 usage decreases to: 2
1842DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
1843- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051803
1844- DTAP matches expected message
1845DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_IMEISV
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1846DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1847DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
1848DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0)
1849DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1850DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1851- MS replies with an Identity Response, causes LU to commence with a GSUP LU request to HLR
1852 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1853DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1854DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
1855DMM IDENTITY RESPONSE: MI(IMEI-SV)=5234234234234276
1856DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=5234234234234276
1857DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: Received Event VLR_ULA_E_ID_IMEISV
1858DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node1()
1859DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_auth()
1860DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_ciph()
1861DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node_4()
1862DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1863DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1864DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1865DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1866DVLR GSUP tx: 04010809710000004026f0
1867GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1868DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1869DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
1870DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1871DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1872 lu_result_sent == 0
1873- Subscriber has the IMEISV from the ID Response
1874DREF VLR subscr MSISDN:46071 usage increases to: 3
1875 strcmp(vsub->imeisv, "5234234234234276") == 0
1876DREF VLR subscr MSISDN:46071 usage decreases to: 2
1877- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1878<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1879DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1880DREF VLR subscr MSISDN:46071 usage increases to: 3
1881DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]1882DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=3)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1883DVLR GSUP tx: 12010809710000004026f0
1884GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1885DREF VLR subscr MSISDN:46071 usage decreases to: 2
1886<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1887 lu_result_sent == 0
1888- having received subscriber data does not mean acceptance
1889msc_subscr_conn_is_accepted() == false
1890 requests shall be thwarted
1891DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1892DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1893DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1894DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1895DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1896DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1897DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1898DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1899 lu_result_sent == 0
1900- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1901<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1902DVLR GSUP rx 11: 06010809710000004026f0
1903DREF VLR subscr MSISDN:46071 usage increases to: 3
1904DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1905DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1906DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1907DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1908DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1909DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1910DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1911DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1912DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1913DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1914DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1915DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1916DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1917DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1918DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1919DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1920DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1921DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1922DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1923DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1924DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1925DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1926DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1927DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1928- sending LU Accept for MSISDN:46071, with TMSI 0x07060504
1929DREF VLR subscr MSISDN:46071 usage decreases to: 2
1930<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1931- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1932 llist_count(&net->subscr_conns) == 1
1933 lu_result_sent == 1
1934msc_subscr_conn_is_accepted() == false
1935 requests shall be thwarted
1936DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1937DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1938DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1939DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1940DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1941DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]1942DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1943DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1944- even though the TMSI is not acked, we can already find the subscr with it
1945DREF VLR subscr MSISDN:46071 usage increases to: 3
1946 vsub != NULL == 1
1947 strcmp(vsub->imsi, imsi) == 0
1948 vsub->tmsi_new == 0x07060504
1949 vsub->tmsi == 0x03020100
1950DREF VLR subscr MSISDN:46071 usage decreases to: 2
1951- MS sends TMSI Realloc Complete
1952 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1953DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1954DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1955DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1956DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1957DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1958DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1959DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1960DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1961DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1962DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1963DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1964DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1965DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1966DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1967DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1968DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
1969DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
1970DREF VLR subscr MSISDN:46071 usage increases to: 3
1971DREF VLR subscr MSISDN:46071 usage decreases to: 2
1972- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1973DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
1974 bssap_clear_sent == 1
1975- LU was successful, and the conn has already been closed
1976- BSS sends BSSMAP Clear Complete
1977DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1978DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1979DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1980DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1981DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1982DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1983DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1984DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1985DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1986DRLL MSISDN:46071: Freeing subscriber connection
1987DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1988DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1989DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]1990 llist_count(&net->subscr_conns) == 0
1991- subscriber has the new TMSI
1992DREF VLR subscr MSISDN:46071 usage increases to: 2
1993 vsub != NULL == 1
1994 strcmp(vsub->imsi, imsi) == 0
1995 vsub->tmsi_new == 0xffffffff
1996 vsub->tmsi == 0x07060504
1997DREF VLR subscr MSISDN:46071 usage decreases to: 1
1998---
1999- subscriber detaches, using new TMSI
2000 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
2001 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2002DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]2003DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2004DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
2005DMM IMSI DETACH INDICATION: MI(TMSI)=117835012
2006DREF VLR subscr MSISDN:46071 usage increases to: 2
2007DMM IMSI DETACH for MSISDN:46071
2008DREF VLR subscr MSISDN:46071 usage decreases to: 1
2009DREF VLR subscr MSISDN:46071 usage decreases to: 0
2010DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2011DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
2012DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
2013DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
2014DREF unknown: MSC conn use + release == 2 (0x101)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2015- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]2016DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
2017 bssap_clear_sent == 1
2018- BSS sends BSSMAP Clear Complete
2019DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2020DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
2021DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
2022DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2023DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2024DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
2025DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2026 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]2027===== test_no_authen_imeisv_tmsi: SUCCESS
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2028
2029full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]2030talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2031
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]2032===== test_no_authen_imeisv_tmsi_imei
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2033- Location Update request causes an IMEISV ID request back to the MS
2034 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
2035 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2036DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]2037DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2038DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame]2039DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2040DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]2041DMM LU/new-LAC: 1/23
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2042DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
2043DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
2044DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
2045DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
2046DREF VLR subscr unknown usage increases to: 1
2047DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
2048DVLR New subscr, IMSI: 901700000004620
2049DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2050DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2051DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A
2052- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051803
2053- DTAP matches expected message
2054DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_IMEISV
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2055DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
2056DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
2057DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0)
2058DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
2059DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2060- MS replies with an Identity Response, causes LU to commence with a GSUP LU request to HLR
2061 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2062DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2063DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
2064DMM IDENTITY RESPONSE: MI(IMEI-SV)=4234234234234275
2065DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=4234234234234275
2066DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: Received Event VLR_ULA_E_ID_IMEISV
2067DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node1()
2068DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_auth()
2069DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_post_ciph()
2070DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: vlr_loc_upd_node_4()
2071DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_IMEISV}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
2072DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
2073DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
2074DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
2075DVLR GSUP tx: 04010809710000004026f0
2076GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
2077DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2078DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
2079DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
2080DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2081 lu_result_sent == 0
2082- Subscriber has the IMEISV from the ID Response
2083DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2084 strcmp(vsub->imeisv, "4234234234234275") == 0
2085DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2086- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
2087<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
2088DVLR GSUP rx 17: 10010809710000004026f00804036470f1
2089DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2090DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]2091DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2092DVLR GSUP tx: 12010809710000004026f0
2093GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
2094DREF VLR subscr MSISDN:46071 usage decreases to: 1
2095<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
2096 lu_result_sent == 0
2097- having received subscriber data does not mean acceptance
2098msc_subscr_conn_is_accepted() == false
2099 requests shall be thwarted
2100DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2101DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2102DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2103DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
2104DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2105DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]2106DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2107DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2108 lu_result_sent == 0
2109- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
2110<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
2111DVLR GSUP rx 11: 06010809710000004026f0
2112DREF VLR subscr MSISDN:46071 usage increases to: 2
2113DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
2114DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
2115DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
2116DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2117DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
2118DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
2119DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
2120DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
2121DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
2122DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
2123DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
2124DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
2125DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
2126DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
2127DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
2128DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
2129DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
2130DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2131DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
2132DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
2133DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
2134DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
2135DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI_TMSI
2136DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
2137- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
2138- DTAP matches expected message
2139DREF VLR subscr MSISDN:46071 usage decreases to: 1
2140<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
2141- We will only do business when the IMEI is known
2142 llist_count(&net->subscr_conns) == 1
2143DREF VLR subscr MSISDN:46071 usage increases to: 2
2144 vsub->imei[0] == 0
2145DREF VLR subscr MSISDN:46071 usage decreases to: 1
2146msc_subscr_conn_is_accepted() == false
2147 requests shall be thwarted
2148DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2149DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2150DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2151DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
2152DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2153DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]2154DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2155DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2156- MS replies with an Identity Response
2157 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2158DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2159DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
2160DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
2161DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
2162DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
2163DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
2164DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
2165DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
2166- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2167DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
2168DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
2169DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2170- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
2171 llist_count(&net->subscr_conns) == 1
2172 lu_result_sent == 1
2173msc_subscr_conn_is_accepted() == false
2174 requests shall be thwarted
2175DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2176DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2177DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2178DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
2179DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2180DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100[diff] [blame]2181DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2182DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2183- MS sends TMSI Realloc Complete
2184 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2185DREF MSISDN:46071: MSC conn use + dtap == 1 (0x2)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2186DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
2187DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
2188DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
2189DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
2190DREF VLR subscr MSISDN:46071 usage increases to: 2
2191DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
2192DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
2193DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2194DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
2195DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
2196DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
2197DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2198DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
2199DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
2200DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
2201DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
2202DREF MSISDN:46071: MSC conn use + release == 2 (0x102)
2203DREF VLR subscr MSISDN:46071 usage increases to: 3
2204DREF VLR subscr MSISDN:46071 usage decreases to: 2
2205- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]2206DREF MSISDN:46071: MSC conn use - dtap == 1 (0x100)
2207 bssap_clear_sent == 1
2208- LU was successful, and the conn has already been closed
2209 lu_result_sent == 1
2210- BSS sends BSSMAP Clear Complete
2211DREF MSISDN:46071: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2212DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
2213DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2214DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2215DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2216DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
2217DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
2218DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
2219DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2220DRLL MSISDN:46071: Freeing subscriber connection
2221DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2222DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
2223DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2224 llist_count(&net->subscr_conns) == 0
2225- Subscriber has the IMEISV, IMEI and TMSI
2226DREF VLR subscr MSISDN:46071 usage increases to: 2
2227 strcmp(vsub->imeisv, "4234234234234275") == 0
2228 strcmp(vsub->imei, "423423423423420") == 0
2229 vsub->tmsi == 0x03020100
2230DREF VLR subscr MSISDN:46071 usage decreases to: 1
2231---
2232- subscriber detaches
2233 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
2234 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2235DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]2236DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2237DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
2238DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
2239DREF VLR subscr MSISDN:46071 usage increases to: 2
2240DMM IMSI DETACH for MSISDN:46071
2241DREF VLR subscr MSISDN:46071 usage decreases to: 1
2242DREF VLR subscr MSISDN:46071 usage decreases to: 0
2243DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2244DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
2245DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
2246DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
2247DREF unknown: MSC conn use + release == 2 (0x101)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2248- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]2249DREF unknown: MSC conn use - compl_l3 == 1 (0x100)
2250 bssap_clear_sent == 1
2251- BSS sends BSSMAP Clear Complete
2252DREF unknown: MSC conn use - release == 0 (0x0)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2253DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
2254DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
2255DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2256DRLL Freeing subscriber connection with NULL subscriber
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]2257DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
2258DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2259 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]2260===== test_no_authen_imeisv_tmsi_imei: SUCCESS
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2261
2262full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]2263talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +0200[diff] [blame]2264
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]2265full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]2266talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]2267