blob: ff9f869a12ae8a4832df67da2b98f1025379cd63 [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2talloc_total_blocks(tall_bsc_ctx) == 12
3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01004===== test_gsm_authen
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01005- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01006 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01007 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01008DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01009DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010010DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +020011DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
12DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
13DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010014DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +010015DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010016DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
17DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
18DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
19DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
20DREF VLR subscr unknown usage increases to: 1
21DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
22DVLR New subscr, IMSI: 901700000004620
23DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +020024DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010025DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
26DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
27DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
28DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
29DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
30DVLR GSUP tx: 08010809710000004026f0
31GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
32DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010033DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010034DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010035 lu_result_sent == 0
36- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
37<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
38DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
39DREF VLR subscr IMSI:901700000004620 usage increases to: 2
40DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
41DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
42DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +010043DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010044- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
45- ...rand=585df1ae287f6e273dce07090d61320b
46- ...expecting sres=2d8b2c3e
47DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
48<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
49 auth_request_sent == 1
50 lu_result_sent == 0
51- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
52<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
53DVLR GSUP rx 11: 06010809710000004026f0
54DREF VLR subscr IMSI:901700000004620 usage increases to: 2
55DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
56DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
57DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
58<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
59msc_subscr_conn_is_accepted() == false
60 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +010061DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
62DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
63DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
64DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
65DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
66DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +010067DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
68DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010069 lu_result_sent == 0
70- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +010071 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +010072DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010073DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010074DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
75DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +010076DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010077DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
78DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
79DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
80DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
81DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
82DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
83DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
84DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
85DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
86DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
87DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
88DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
89DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
90DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
91DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
92DVLR GSUP tx: 04010809710000004026f0
93GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
94DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010095DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010096DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010097 lu_result_sent == 0
98- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
99<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
100DVLR GSUP rx 17: 10010809710000004026f00804036470f1
101DREF VLR subscr IMSI:901700000004620 usage increases to: 2
102DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100103DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100104DVLR GSUP tx: 12010809710000004026f0
105GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
106DREF VLR subscr MSISDN:46071 usage decreases to: 1
107<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
108 lu_result_sent == 0
109- HLR also sends GSUP _UPDATE_LOCATION_RESULT
110<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
111DVLR GSUP rx 11: 06010809710000004026f0
112DREF VLR subscr MSISDN:46071 usage increases to: 2
113DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
114DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
115DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
116DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
117DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
118DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
119DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
120DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
121DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
122DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
123DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
124DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
125DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
126DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
127DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
128DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
129DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
130DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
131DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
132DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
133DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
134DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
135- sending LU Accept for MSISDN:46071
136DREF VLR subscr MSISDN:46071 usage increases to: 3
137DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
138DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
139DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
140DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
141DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
142DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
143DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200144DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
145DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
146DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100147DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
148DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200149DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
150DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100151DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
152DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
153DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
154DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
155DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
156DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200157- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100158DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100159DRLL subscr MSISDN:46071: Freeing subscriber connection
160DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200161DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
162DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100163DREF VLR subscr MSISDN:46071 usage decreases to: 1
164<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +0200165 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100166- LU was successful, and the conn has already been closed
167 lu_result_sent == 1
168 llist_count(&net->subscr_conns) == 0
169---
170- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100171 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100172 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100173DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100174DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100175DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100176DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200177DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
178DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
179DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100180DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
181DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
182DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
183DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
184DREF VLR subscr MSISDN:46071 usage increases to: 2
185DREF VLR subscr MSISDN:46071 usage increases to: 3
186DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
187DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
188DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
189DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
190DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
191DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100192DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100193- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
194- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
195- ...expecting sres=20bde240
196DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100197DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100198DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100199 cm_service_result_sent == 0
200 auth_request_sent == 1
201- needs auth, not yet accepted
202msc_subscr_conn_is_accepted() == false
203 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100204DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
205DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
206DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
207DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
208DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
209DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100210DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
211DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100212- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100213 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100214DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100215DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100216DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
217DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100218DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100219DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
220DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
221DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
222DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
223DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
224DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
225DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
226DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
227DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
228DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
229DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
230DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
231DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
232DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
233DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
234DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
235DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
236DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
237- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200238DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
239DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
240DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
241DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100242DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
243DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
244DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
245DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100246DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100247 cm_service_result_sent == 1
248- a USSD request is serviced
249 expecting USSD:
250 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100251 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100252DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100253DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
254DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200255DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
256DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100257DMM USSD: Own number requested
258DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200259DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100260- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100261- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100262DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
263DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200264DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
265DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100266DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
267DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
268DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
269DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
270DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200271- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100272DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200273DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
274DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100275DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100276DRLL subscr MSISDN:46071: Freeing subscriber connection
277DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200278 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100279- all requests serviced, conn has been released
280 llist_count(&net->subscr_conns) == 0
281---
282- an SMS is sent, MS is paged
283DREF VLR subscr MSISDN:46071 usage increases to: 2
284 llist_count(&vsub->cs.requests) == 0
285DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200286DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100287 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200288 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100289DREF VLR subscr MSISDN:46071 usage increases to: 4
290 llist_count(&vsub->cs.requests) == 1
291DREF VLR subscr MSISDN:46071 usage decreases to: 3
292 paging_sent == 1
293 paging_stopped == 0
294- the subscriber and its pending request should remain
295DREF VLR subscr MSISDN:46071 usage increases to: 4
296 llist_count(&vsub->cs.requests) == 1
297DREF VLR subscr MSISDN:46071 usage decreases to: 3
298- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100299 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100300 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100301DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100302DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100303DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100304DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200305DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
306DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
307DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100308DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
309DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
310DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
311DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
312DREF VLR subscr MSISDN:46071 usage increases to: 4
313DREF VLR subscr MSISDN:46071 usage increases to: 5
314DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
315DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
316DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
317DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
318DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
319DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100320DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100321- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
322- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
323- ...expecting sres=a29514ae
324DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100325DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100326DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100327 auth_request_sent == 1
328- needs auth, not yet accepted
329msc_subscr_conn_is_accepted() == false
330 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100331DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
332DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
333DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
334DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
335DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
336DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100337DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
338DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100339- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100340 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100341DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100342DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100343DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
344DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100345DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100346DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
347DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
348DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
349DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
350DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
351DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
352DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
353DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
354DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
355DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
356DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
357DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
358DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
359DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
360DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
361DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
362DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
363DVLR 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 +0200364DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
365DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
366DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
367DPAG Paging success for MSISDN:46071 (event=0)
368DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100369DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100370DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100371DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200372DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100373- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100374- DTAP matches expected message
375DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100376DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
377DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
378DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
379DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100380DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100381 dtap_tx_confirmed == 1
382 paging_stopped == 1
383- SMS was delivered, no requests pending for subscr
384DREF VLR subscr MSISDN:46071 usage increases to: 5
385 llist_count(&vsub->cs.requests) == 0
386DREF VLR subscr MSISDN:46071 usage decreases to: 4
387- conn is still open to wait for SMS ack dance
388 llist_count(&net->subscr_conns) == 1
389- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100390 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100391DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100392DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200393DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
394DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100395DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
396DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100397DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100398 llist_count(&net->subscr_conns) == 1
399- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100400 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100401DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100402DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200403DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
404DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100405- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100406- DTAP matches expected message
407DREF VLR subscr MSISDN:46071 usage decreases to: 3
408DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100409DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100410DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
411DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200412DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
413DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100414DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
415DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
416DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
417DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
418DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200419- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100420DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200421DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
422DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100423DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100424DRLL subscr MSISDN:46071: Freeing subscriber connection
425DREF VLR subscr MSISDN:46071 usage decreases to: 1
426 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200427 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100428- SMS is done, conn is gone
429 llist_count(&net->subscr_conns) == 0
430---
431- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100432 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100433 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100434DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100435DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100436DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
437DREF VLR subscr MSISDN:46071 usage increases to: 2
438DMM IMSI DETACH for MSISDN:46071
439DREF VLR subscr MSISDN:46071 usage decreases to: 1
440DREF VLR subscr MSISDN:46071 usage decreases to: 0
441DREF freeing VLR subscr MSISDN:46071
442DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200443- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100444DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100445DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200446 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100447 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100448===== test_gsm_authen: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100449
450full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200451talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100452
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100453===== test_gsm_authen_tmsi
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100454- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100455 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100456 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100457DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100458DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100459DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200460DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
461DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
462DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100463DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100464DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100465DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
466DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
467DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
468DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
469DREF VLR subscr unknown usage increases to: 1
470DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
471DVLR New subscr, IMSI: 901700000004620
472DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200473DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100474DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
475DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
476DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
477DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
478DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
479DVLR GSUP tx: 08010809710000004026f0
480GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
481DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100482DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100483DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100484 lu_result_sent == 0
485- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
486<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
487DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
488DREF VLR subscr IMSI:901700000004620 usage increases to: 2
489DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
490DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
491DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100492DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100493- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
494- ...rand=585df1ae287f6e273dce07090d61320b
495- ...expecting sres=2d8b2c3e
496DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
497<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
498 auth_request_sent == 1
499 lu_result_sent == 0
500- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
501<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
502DVLR GSUP rx 11: 06010809710000004026f0
503DREF VLR subscr IMSI:901700000004620 usage increases to: 2
504DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
505DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
506DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
507<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
508msc_subscr_conn_is_accepted() == false
509 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100510DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
511DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
512DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
513DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
514DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
515DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100516DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
517DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100518 lu_result_sent == 0
519- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100520 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100521DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100522DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100523DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
524DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100525DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100526DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
527DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
528DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
529DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
530DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
531DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
532DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
533DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
534DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
535DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
536DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
537DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
538DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
539DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
540DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
541DVLR GSUP tx: 04010809710000004026f0
542GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
543DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100544DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100545DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100546 lu_result_sent == 0
547- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
548<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
549DVLR GSUP rx 17: 10010809710000004026f00804036470f1
550DREF VLR subscr IMSI:901700000004620 usage increases to: 2
551DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100552DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100553DVLR GSUP tx: 12010809710000004026f0
554GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
555DREF VLR subscr MSISDN:46071 usage decreases to: 1
556<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
557 lu_result_sent == 0
558- HLR also sends GSUP _UPDATE_LOCATION_RESULT
559<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
560DVLR GSUP rx 11: 06010809710000004026f0
561DREF VLR subscr MSISDN:46071 usage increases to: 2
562DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
563DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
564DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
565DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
566DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
567DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
568DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
569DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
570DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
571DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
572DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
573DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
574DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
575DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
576DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
577DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
578DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
579DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
580DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
581DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
582DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
583DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
584DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
585DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
586- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
587DREF VLR subscr MSISDN:46071 usage decreases to: 1
588<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
589- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
590 llist_count(&net->subscr_conns) == 1
591 lu_result_sent == 1
592msc_subscr_conn_is_accepted() == false
593 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100594DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
595DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
596DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
597DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
598DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
599DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100600DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
601DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100602- even though the TMSI is not acked, we can already find the subscr with it
603DREF VLR subscr MSISDN:46071 usage increases to: 2
604 vsub != NULL == 1
605 strcmp(vsub->imsi, imsi) == 0
606 vsub->tmsi_new == 0x03020100
607 vsub->tmsi == 0xffffffff
608DREF VLR subscr MSISDN:46071 usage decreases to: 1
609- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100610 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100611DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100612DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100613DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
614DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
615DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
616DREF VLR subscr MSISDN:46071 usage increases to: 2
617DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
618DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
619DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
620DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
621DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
622DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
623DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200624DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
625DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
626DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100627DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
628DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200629DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
630DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100631DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
632DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
633DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
634DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
635DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
636DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200637- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100638DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200639DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
640DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100641DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100642DRLL subscr MSISDN:46071: Freeing subscriber connection
643DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200644 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100645- LU was successful, and the conn has already been closed
646 llist_count(&net->subscr_conns) == 0
647- Subscriber has the new TMSI
648DREF VLR subscr MSISDN:46071 usage increases to: 2
649 vsub != NULL == 1
650 strcmp(vsub->imsi, imsi) == 0
651 vsub->tmsi_new == 0xffffffff
652 vsub->tmsi == 0x03020100
653DREF VLR subscr MSISDN:46071 usage decreases to: 1
654---
655- after a while, a new conn sends a CM Service Request using above TMSI. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100656 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100657 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100658DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100659DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100660DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100661DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200662DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
663DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
664DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100665DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
666DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
667DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
668DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
669DREF VLR subscr MSISDN:46071 usage increases to: 2
670DREF VLR subscr MSISDN:46071 usage increases to: 3
671DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
672DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
673DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
674DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
675DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
676DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100677DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100678- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
679- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
680- ...expecting sres=20bde240
681DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100682DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100683DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100684 cm_service_result_sent == 0
685 auth_request_sent == 1
686- needs auth, not yet accepted
687msc_subscr_conn_is_accepted() == false
688 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100689DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
690DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
691DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
692DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
693DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
694DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100695DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
696DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100697- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100698 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100699DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100700DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100701DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
702DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100703DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100704DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
705DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
706DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
707DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
708DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
709DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
710DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
711DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
712DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
713DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
714DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
715DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
716DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
717DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
718DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
719DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
720DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
721DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
722- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200723DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
724DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
725DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
726DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100727DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
728DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
729DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
730DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100731DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100732 cm_service_result_sent == 1
733- a USSD request is serviced
734 expecting USSD:
735 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100736 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100737DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100738DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
739DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200740DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
741DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100742DMM USSD: Own number requested
743DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200744DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100745- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100746- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100747DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
748DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200749DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
750DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100751DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
752DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
753DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
754DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
755DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200756- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100757DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200758DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
759DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100760DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100761DRLL subscr MSISDN:46071: Freeing subscriber connection
762DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200763 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100764- all requests serviced, conn has been released
765 llist_count(&net->subscr_conns) == 0
766---
767- an SMS is sent, MS is paged
768DREF VLR subscr MSISDN:46071 usage increases to: 2
769 llist_count(&vsub->cs.requests) == 0
770DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200771DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100772 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100773 paging_expecting_tmsi == 0x03020100
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100774DREF VLR subscr MSISDN:46071 usage increases to: 4
775 llist_count(&vsub->cs.requests) == 1
776DREF VLR subscr MSISDN:46071 usage decreases to: 3
777 paging_sent == 1
778 paging_stopped == 0
779- the subscriber and its pending request should remain
780DREF VLR subscr MSISDN:46071 usage increases to: 4
781 llist_count(&vsub->cs.requests) == 1
782DREF VLR subscr MSISDN:46071 usage decreases to: 3
783- MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100784 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100785 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100786DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100787DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100788DRR PAGING RESPONSE: MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100789DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200790DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
791DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
792DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100793DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
794DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
795DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
796DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
797DREF VLR subscr MSISDN:46071 usage increases to: 4
798DREF VLR subscr MSISDN:46071 usage increases to: 5
799DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
800DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
801DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
802DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
803DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
804DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100805DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100806- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
807- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
808- ...expecting sres=a29514ae
809DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100810DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100811DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100812 auth_request_sent == 1
813- needs auth, not yet accepted
814msc_subscr_conn_is_accepted() == false
815 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100816DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
817DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
818DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
819DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
820DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
821DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100822DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
823DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100824- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100825 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100826DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100827DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100828DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
829DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100830DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100831DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
832DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
833DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
834DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
835DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
836DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
837DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
838DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
839DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
840DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
841DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
842DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
843DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
844DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
845DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
846DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
847DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
848DVLR 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 +0200849DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
850DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
851DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
852DPAG Paging success for MSISDN:46071 (event=0)
853DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100854DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100855DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100856DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200857DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100858- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100859- DTAP matches expected message
860DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100861DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
862DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
863DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
864DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100865DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100866 dtap_tx_confirmed == 1
867 paging_stopped == 1
868- SMS was delivered, no requests pending for subscr
869DREF VLR subscr MSISDN:46071 usage increases to: 5
870 llist_count(&vsub->cs.requests) == 0
871DREF VLR subscr MSISDN:46071 usage decreases to: 4
872- conn is still open to wait for SMS ack dance
873 llist_count(&net->subscr_conns) == 1
874- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100875 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100876DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100877DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200878DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
879DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100880DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
881DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100882DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100883 llist_count(&net->subscr_conns) == 1
884- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100885 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100886DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100887DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200888DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
889DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100890- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100891- DTAP matches expected message
892DREF VLR subscr MSISDN:46071 usage decreases to: 3
893DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100894DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100895DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
896DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200897DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
898DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100899DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
900DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
901DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
902DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
903DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200904- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100905DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200906DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
907DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100908DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100909DRLL subscr MSISDN:46071: Freeing subscriber connection
910DREF VLR subscr MSISDN:46071 usage decreases to: 1
911 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200912 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100913- SMS is done, conn is gone
914 llist_count(&net->subscr_conns) == 0
915---
916- subscriber sends LU Request, this time with the TMSI
917- Location Update request causes an Auth Req to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100918 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100919 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100920DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100921DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100922DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200923DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
924DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
925DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100926DMM LOCATION UPDATING REQUEST: MI(TMSI)=50462976 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100927DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100928DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Allocated
929DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: is child of Subscr_Conn(50462976)
930DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
931DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
932DREF VLR subscr MSISDN:46071 usage increases to: 2
933DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200934DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100935DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
936DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
937DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
938DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(50462976)
939DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
940DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100941DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=3 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100942- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=3 auth_types=0x1 and...
943- ...rand=fa8f20b781b5881329d4fea26b1a3c51
944- ...expecting sres=5afc8d72
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100945DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100946DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100947 auth_request_sent == 1
948 lu_result_sent == 0
949- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100950 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100951DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100952DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100953DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 5afc8d72)
954DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100955DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 5afc8d72 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100956DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
957DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
958DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
959DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
960DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(50462976)
961DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
962DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
963DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
964DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
965DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
966DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
967DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
968DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Allocated
969DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
970DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
971DVLR GSUP tx: 04010809710000004026f0
972GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
973DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100974DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100975DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100976 lu_result_sent == 0
977- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
978<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
979DVLR GSUP rx 17: 10010809710000004026f00804036470f1
980DREF VLR subscr MSISDN:46071 usage increases to: 3
981DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100982DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100983DVLR GSUP tx: 12010809710000004026f0
984GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
985DREF VLR subscr MSISDN:46071 usage decreases to: 2
986<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
987 lu_result_sent == 0
988- HLR also sends GSUP _UPDATE_LOCATION_RESULT
989<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
990DVLR GSUP rx 11: 06010809710000004026f0
991DREF VLR subscr MSISDN:46071 usage increases to: 3
992DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
993DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
994DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
995DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
996DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
997DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Freeing instance
998DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Deallocated
999DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1000DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1001DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Allocated
1002DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
1003DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1004DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1005DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Allocated
1006DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(50462976)
1007DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1008DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1009DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1010DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(50462976)
1011DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Freeing instance
1012DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Deallocated
1013DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1014DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1015DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1016- sending LU Accept for MSISDN:46071, with TMSI 0x07060504
1017DREF VLR subscr MSISDN:46071 usage decreases to: 2
1018<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1019- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1020 llist_count(&net->subscr_conns) == 1
1021 lu_result_sent == 1
1022msc_subscr_conn_is_accepted() == false
1023 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001024DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1025DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1026DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1027DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1028DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1029DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001030DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1031DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001032- even though the TMSI is not acked, we can already find the subscr with it
1033DREF VLR subscr MSISDN:46071 usage increases to: 3
1034 vsub != NULL == 1
1035 strcmp(vsub->imsi, imsi) == 0
1036 vsub->tmsi_new == 0x07060504
1037 vsub->tmsi == 0x03020100
1038DREF VLR subscr MSISDN:46071 usage decreases to: 2
1039- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001040 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001041DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001042DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001043DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1044DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1045DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1046DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1047DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1048DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1049DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
1050DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Freeing instance
1051DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Deallocated
1052DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001053DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1054DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1055DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001056DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1057DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001058DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1059DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001060DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1061DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(50462976)
1062DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1063DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Freeing instance
1064DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Deallocated
1065DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001066- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001067DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001068DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
1069DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001070DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001071DRLL subscr MSISDN:46071: Freeing subscriber connection
1072DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001073 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001074- LU was successful, and the conn has already been closed
1075 llist_count(&net->subscr_conns) == 0
1076- subscriber has the new TMSI
1077DREF VLR subscr MSISDN:46071 usage increases to: 2
1078 vsub != NULL == 1
1079 strcmp(vsub->imsi, imsi) == 0
1080 vsub->tmsi_new == 0xffffffff
1081 vsub->tmsi == 0x07060504
1082DREF VLR subscr MSISDN:46071 usage decreases to: 1
1083---
1084- subscriber detaches, using new TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001085 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001086 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001087DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001088DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001089DMM IMSI DETACH INDICATION: MI(TMSI)=117835012
1090DREF VLR subscr MSISDN:46071 usage increases to: 2
1091DMM IMSI DETACH for MSISDN:46071
1092DREF VLR subscr MSISDN:46071 usage decreases to: 1
1093DREF VLR subscr MSISDN:46071 usage decreases to: 0
1094DREF freeing VLR subscr MSISDN:46071
1095DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001096- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001097DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001098DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001099 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001100 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001101===== test_gsm_authen_tmsi: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001102
1103full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001104talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001105
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001106===== test_gsm_authen_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001107- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001108 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001109 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001110DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001111DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001112DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001113DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1114DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1115DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001116DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001117DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001118DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1119DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1120DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1121DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1122DREF VLR subscr unknown usage increases to: 1
1123DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1124DVLR New subscr, IMSI: 901700000004620
1125DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001126DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001127DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1128DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1129DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1130DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1131DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1132DVLR GSUP tx: 08010809710000004026f0
1133GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1134DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001135DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001136DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001137 lu_result_sent == 0
1138- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1139<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1140DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1141DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1142DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1143DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1144DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001145DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001146- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1147- ...rand=585df1ae287f6e273dce07090d61320b
1148- ...expecting sres=2d8b2c3e
1149DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1150<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1151 auth_request_sent == 1
1152 lu_result_sent == 0
1153- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
1154<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1155DVLR GSUP rx 11: 06010809710000004026f0
1156DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1157DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
1158DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
1159DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1160<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1161msc_subscr_conn_is_accepted() == false
1162 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001163DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1164DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1165DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1166DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1167DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1168DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001169DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1170DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001171 lu_result_sent == 0
1172- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001173 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001174DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001175DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001176DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1177DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001178DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001179DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1180DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1181DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1182DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1183DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1184DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1185DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1186DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1187DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1188DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1189DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1190DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1191DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1192DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1193DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1194DVLR GSUP tx: 04010809710000004026f0
1195GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1196DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001197DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001198DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001199 lu_result_sent == 0
1200- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1201<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1202DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1203DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1204DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001205DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001206DVLR GSUP tx: 12010809710000004026f0
1207GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1208DREF VLR subscr MSISDN:46071 usage decreases to: 1
1209<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1210 lu_result_sent == 0
1211- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1212<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1213DVLR GSUP rx 11: 06010809710000004026f0
1214DREF VLR subscr MSISDN:46071 usage increases to: 2
1215DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1216DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1217DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1218DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1219DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1220DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1221DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1222DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1223DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1224DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1225DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1226DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1227DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1228DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1229DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1230DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1231DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1232DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1233DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1234DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1235DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1236DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1237DVLR 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 +02001238DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001239- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001240- DTAP matches expected message
1241DREF VLR subscr MSISDN:46071 usage decreases to: 1
1242<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1243- We will only do business when the IMEI is known
1244 llist_count(&net->subscr_conns) == 1
1245DREF VLR subscr MSISDN:46071 usage increases to: 2
1246 vsub->imei[0] == 0
1247DREF VLR subscr MSISDN:46071 usage decreases to: 1
1248msc_subscr_conn_is_accepted() == false
1249 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001250DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1251DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1252DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1253DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1254DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1255DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001256DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1257DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001258- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001259 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001260DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001261DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001262DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1263DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001264DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1265DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1266- sending LU Accept for MSISDN:46071
1267DREF VLR subscr MSISDN:46071 usage increases to: 2
1268DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
1269DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1270DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1271DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1272DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1273DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1274DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001275DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1276DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1277DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001278DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1279DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001280DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1281DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001282DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1283DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1284DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1285DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1286DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1287DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001288- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001289DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001290DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1291DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001292DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001293DRLL subscr MSISDN:46071: Freeing subscriber connection
1294DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001295 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001296- LU was successful, and the conn has already been closed
1297 lu_result_sent == 1
1298 llist_count(&net->subscr_conns) == 0
1299- Subscriber has the IMEI
1300DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001301 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001302DREF VLR subscr MSISDN:46071 usage decreases to: 1
1303---
1304- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001305 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001306 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001307DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001308DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001309DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1310DREF VLR subscr MSISDN:46071 usage increases to: 2
1311DMM IMSI DETACH for MSISDN:46071
1312DREF VLR subscr MSISDN:46071 usage decreases to: 1
1313DREF VLR subscr MSISDN:46071 usage decreases to: 0
1314DREF freeing VLR subscr MSISDN:46071
1315DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001316- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001317DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001318DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001319 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001320 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001321===== test_gsm_authen_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001322
1323full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001324talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001325
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001326===== test_gsm_authen_tmsi_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001327- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001328 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001329 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001330DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001331DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001332DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001333DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1334DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1335DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001336DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001337DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001338DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1339DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1340DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1341DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1342DREF VLR subscr unknown usage increases to: 1
1343DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1344DVLR New subscr, IMSI: 901700000004620
1345DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001346DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001347DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1348DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1349DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1350DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1351DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1352DVLR GSUP tx: 08010809710000004026f0
1353GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1354DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001355DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001356DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001357 lu_result_sent == 0
1358- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1359<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1360DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1361DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1362DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1363DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1364DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001365DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001366- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1367- ...rand=585df1ae287f6e273dce07090d61320b
1368- ...expecting sres=2d8b2c3e
1369DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1370<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1371 auth_request_sent == 1
1372 lu_result_sent == 0
1373- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
1374<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1375DVLR GSUP rx 11: 06010809710000004026f0
1376DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1377DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
1378DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
1379DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1380<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1381msc_subscr_conn_is_accepted() == false
1382 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001383DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1384DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1385DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1386DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1387DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1388DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001389DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1390DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001391 lu_result_sent == 0
1392- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001393 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001394DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001395DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001396DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1397DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001398DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001399DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1400DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1401DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1402DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1403DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1404DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1405DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1406DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1407DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1408DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1409DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1410DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1411DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1412DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1413DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1414DVLR GSUP tx: 04010809710000004026f0
1415GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1416DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001417DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001418DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001419 lu_result_sent == 0
1420- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1421<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1422DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1423DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1424DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001425DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001426DVLR GSUP tx: 12010809710000004026f0
1427GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1428DREF VLR subscr MSISDN:46071 usage decreases to: 1
1429<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1430 lu_result_sent == 0
1431- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1432<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1433DVLR GSUP rx 11: 06010809710000004026f0
1434DREF VLR subscr MSISDN:46071 usage increases to: 2
1435DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1436DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1437DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1438DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1439DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1440DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1441DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1442DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1443DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1444DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1445DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1446DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1447DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1448DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1449DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1450DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1451DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1452DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1453DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1454DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1455DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1456DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1457DVLR 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 +02001458DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001459- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001460- DTAP matches expected message
1461DREF VLR subscr MSISDN:46071 usage decreases to: 1
1462<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1463- We will only do business when the IMEI is known
1464 llist_count(&net->subscr_conns) == 1
1465DREF VLR subscr MSISDN:46071 usage increases to: 2
1466 vsub->imei[0] == 0
1467DREF VLR subscr MSISDN:46071 usage decreases to: 1
1468msc_subscr_conn_is_accepted() == false
1469 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001470DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1471DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1472DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1473DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1474DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1475DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001476DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1477DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001478- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001479 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001480DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001481DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001482DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1483DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001484DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1485DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1486DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
1487DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1488- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001489DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001490DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001491- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1492 llist_count(&net->subscr_conns) == 1
1493 lu_result_sent == 1
1494msc_subscr_conn_is_accepted() == false
1495 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001496DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1497DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1498DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1499DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1500DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1501DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001502DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1503DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001504- even though the TMSI is not acked, we can already find the subscr with it
1505DREF VLR subscr MSISDN:46071 usage increases to: 2
1506 vsub != NULL == 1
1507 strcmp(vsub->imsi, imsi) == 0
1508 vsub->tmsi_new == 0x03020100
1509 vsub->tmsi == 0xffffffff
1510DREF VLR subscr MSISDN:46071 usage decreases to: 1
1511- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001512 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001513DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001514DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001515DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1516DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1517DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1518DREF VLR subscr MSISDN:46071 usage increases to: 2
1519DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1520DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1521DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1522DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1523DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1524DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1525DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001526DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1527DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1528DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001529DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1530DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001531DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1532DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001533DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1534DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1535DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1536DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1537DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1538DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001539- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001540DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001541DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1542DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001543DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001544DRLL subscr MSISDN:46071: Freeing subscriber connection
1545DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001546 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001547- LU was successful, and the conn has already been closed
1548 llist_count(&net->subscr_conns) == 0
1549- Subscriber has the IMEI and TMSI
1550DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001551 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001552 vsub->tmsi == 0x03020100
1553DREF VLR subscr MSISDN:46071 usage decreases to: 1
1554---
1555- subscriber detaches, using TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001556 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001557 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001558DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001559DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001560DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1561DREF VLR subscr MSISDN:46071 usage increases to: 2
1562DMM IMSI DETACH for MSISDN:46071
1563DREF VLR subscr MSISDN:46071 usage decreases to: 1
1564DREF VLR subscr MSISDN:46071 usage decreases to: 0
1565DREF freeing VLR subscr MSISDN:46071
1566DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001567- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001568DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001569DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001570 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001571 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001572===== test_gsm_authen_tmsi_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001573
1574full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001575talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001576
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001577===== test_gsm_milenage_authen
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001578- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001579 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001580 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001581DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001582DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001583DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001584DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1585DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1586DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001587DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001588DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001589DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1590DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1591DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1592DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1593DREF VLR subscr unknown usage increases to: 1
1594DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1595DVLR New subscr, IMSI: 901700000010650
1596DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001597DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001598DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1599DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1600DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1601DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1602DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1603DVLR GSUP tx: 08010809710000000156f0
1604GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1605DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001606DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001607DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001608 lu_result_sent == 0
1609- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1610<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c
1611DVLR GSUP rx 311: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c
1612DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1613DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1614DVLR SUBSCR(IMSI:901700000010650) Received 3 auth tuples
1615DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001616DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001617- sending GSM Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1618- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1619- ...expecting sres=9b36efdf
1620DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1621<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1622 auth_request_sent == 1
1623 lu_result_sent == 0
1624- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001625 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001626DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001627DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001628DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = 9b36efdf)
1629DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001630DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: 9b36efdf (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001631DVLR SUBSCR(IMSI:901700000010650) AUTH established GSM security context
1632DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1633DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1634DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1635DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1636DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1637DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1638DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1639DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1640DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1641DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1642DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1643DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1644DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1645DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1646DVLR GSUP tx: 04010809710000000156f0
1647GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1648DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001649DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001650DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001651 lu_result_sent == 0
1652- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1653<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1654DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1655DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1656DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +01001657DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001658DVLR GSUP tx: 12010809710000000156f0
1659GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1660DREF VLR subscr MSISDN:42342 usage decreases to: 1
1661<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1662 lu_result_sent == 0
1663- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1664<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1665DVLR GSUP rx 11: 06010809710000000156f0
1666DREF VLR subscr MSISDN:42342 usage increases to: 2
1667DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1668DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1669DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1670DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1671DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1672DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1673DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1674DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1675DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1676DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1677DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1678DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1679DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1680DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1681DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1682DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1683DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1684DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1685DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1686DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1687DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1688DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1689- sending LU Accept for MSISDN:42342
1690DREF VLR subscr MSISDN:42342 usage increases to: 3
1691DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1692DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1693DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1694DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1695DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1696DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1697DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001698DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1699DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1700DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001701DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1702DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001703DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1704DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001705DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1706DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1707DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1708DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1709DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1710DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001711- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001712DREF MSISDN:42342: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001713DRLL subscr MSISDN:42342: Freeing subscriber connection
1714DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001715DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1716DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001717DREF VLR subscr MSISDN:42342 usage decreases to: 1
1718<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +02001719 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001720- LU was successful, and the conn has already been closed
1721 lu_result_sent == 1
1722 llist_count(&net->subscr_conns) == 0
1723---
1724- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001725 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001726 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001727DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001728DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001729DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001730DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001731DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1732DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1733DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001734DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1735DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1736DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
1737DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1738DREF VLR subscr MSISDN:42342 usage increases to: 2
1739DREF VLR subscr MSISDN:42342 usage increases to: 3
1740DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1741DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1742DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1743DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1744DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1745DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001746DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001747- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1748- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1749- ...expecting sres=85aa3130
1750DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001751DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001752DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001753 cm_service_result_sent == 0
1754 auth_request_sent == 1
1755- needs auth, not yet accepted
1756msc_subscr_conn_is_accepted() == false
1757 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001758DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1759DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1760DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1761DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1762DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1763DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001764DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1765DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001766- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001767 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001768DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001769DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001770DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 85aa3130)
1771DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001772DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 85aa3130 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001773DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1774DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1775DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1776DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1777DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1778DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1779DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1780DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1781DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1782DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1783DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
1784DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
1785DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
1786DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
1787DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
1788DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1789DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
1790DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1791- sending CM Service Accept for MSISDN:42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001792DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1793DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
1794DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1795DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001796DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1797DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
1798DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1799DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001800DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001801 cm_service_result_sent == 1
1802- a USSD request is serviced
1803 expecting USSD:
1804 Your extension is 42342
Harald Welte80315ef2018-01-24 22:53:00 +01001805 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001806DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +01001807DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
1808DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001809DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1810DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001811DMM USSD: Own number requested
1812DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001813DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001814- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001815- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001816DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1817DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001818DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1819DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001820DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1821DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1822DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1823DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1824DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001825- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001826DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001827DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1828DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001829DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001830DRLL subscr MSISDN:42342: Freeing subscriber connection
1831DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001832 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001833- all requests serviced, conn has been released
1834 llist_count(&net->subscr_conns) == 0
1835---
1836- an SMS is sent, MS is paged
1837DREF VLR subscr MSISDN:42342 usage increases to: 2
1838 llist_count(&vsub->cs.requests) == 0
1839DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001840DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001841 RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001842 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001843DREF VLR subscr MSISDN:42342 usage increases to: 4
1844 llist_count(&vsub->cs.requests) == 1
1845DREF VLR subscr MSISDN:42342 usage decreases to: 3
1846 paging_sent == 1
1847 paging_stopped == 0
1848- the subscriber and its pending request should remain
1849DREF VLR subscr MSISDN:42342 usage increases to: 4
1850 llist_count(&vsub->cs.requests) == 1
1851DREF VLR subscr MSISDN:42342 usage decreases to: 3
1852- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001853 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001854 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001855DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001856DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001857DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001858DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001859DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1860DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1861DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001862DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1863DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1864DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
1865DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1866DREF VLR subscr MSISDN:42342 usage increases to: 4
1867DREF VLR subscr MSISDN:42342 usage increases to: 5
1868DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1869DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1870DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1871DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1872DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1873DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001874DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001875- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
1876- ...rand=efa9c29a9742148d5c9070348716e1bb
1877- ...expecting sres=69d5f9fb
1878DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001879DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001880DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001881 auth_request_sent == 1
1882- needs auth, not yet accepted
1883msc_subscr_conn_is_accepted() == false
1884 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001885DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1886DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1887DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1888DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1889DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1890DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001891DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1892DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001893- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001894 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001895DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001896DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001897DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 69d5f9fb)
1898DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001899DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 69d5f9fb (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001900DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1901DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1902DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1903DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1904DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1905DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1906DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1907DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1908DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1909DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1910DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
1911DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
1912DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
1913DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
1914DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
1915DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1916DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
1917DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001918DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1919DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
1920DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1921DPAG Paging success for MSISDN:42342 (event=0)
1922DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01001923DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001924DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001925DREF MSISDN:42342: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001926DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001927- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001928- DTAP matches expected message
1929DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001930DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1931DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
1932DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1933DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001934DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001935 dtap_tx_confirmed == 1
1936 paging_stopped == 1
1937- SMS was delivered, no requests pending for subscr
1938DREF VLR subscr MSISDN:42342 usage increases to: 5
1939 llist_count(&vsub->cs.requests) == 0
1940DREF VLR subscr MSISDN:42342 usage decreases to: 4
1941- conn is still open to wait for SMS ack dance
1942 llist_count(&net->subscr_conns) == 1
1943- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +01001944 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001945DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +01001946DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001947DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1948DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001949DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1950DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001951DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001952 llist_count(&net->subscr_conns) == 1
1953- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +01001954 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001955DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +01001956DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001957DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1958DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001959- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001960- DTAP matches expected message
1961DREF VLR subscr MSISDN:42342 usage decreases to: 3
1962DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001963DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001964DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1965DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001966DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1967DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001968DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1969DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1970DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1971DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1972DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001973- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001974DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001975DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1976DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001977DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001978DRLL subscr MSISDN:42342: Freeing subscriber connection
1979DREF VLR subscr MSISDN:42342 usage decreases to: 1
1980 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001981 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001982- SMS is done, conn is gone
1983 llist_count(&net->subscr_conns) == 0
1984---
1985- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001986 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001987 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001988DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001989DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001990DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
1991DREF VLR subscr MSISDN:42342 usage increases to: 2
1992DMM IMSI DETACH for MSISDN:42342
1993DREF VLR subscr MSISDN:42342 usage decreases to: 1
1994DREF VLR subscr MSISDN:42342 usage decreases to: 0
1995DREF freeing VLR subscr MSISDN:42342
1996DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001997- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001998DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001999DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02002000 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002001 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01002002===== test_gsm_milenage_authen: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002003
2004full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002005talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002006
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002007===== test_wrong_sres_length
2008- Total time passed: 0.000000 s
2009- Location Update request causes a GSUP Send Auth Info request to HLR
2010 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
2011 new conn
2012DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2013DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
2014DREF unknown: MSC conn use + fsm == 2 (0x5)
2015DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
2016DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
2017DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
2018DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
2019DMM LU/new-LAC: 1/23
2020DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
2021DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
2022DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
2023DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
2024DREF VLR subscr unknown usage increases to: 1
2025DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
2026DVLR New subscr, IMSI: 901700000004620
2027DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2028DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2029DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
2030DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
2031DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
2032DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
2033DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
2034DVLR GSUP tx: 08010809710000004026f0
2035GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
2036DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002037DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002038DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
2039 lu_result_sent == 0
2040- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
2041<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2042DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2043DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2044DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
2045DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
2046DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01002047DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002048- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
2049- ...rand=585df1ae287f6e273dce07090d61320b
2050- ...expecting sres=2d8b2c3e
2051DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2052<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
2053 auth_request_sent == 1
2054 lu_result_sent == 0
2055- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
2056<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
2057DVLR GSUP rx 11: 06010809710000004026f0
2058DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2059DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
2060DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
2061DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2062<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
2063msc_subscr_conn_is_accepted() == false
2064 requests shall be thwarted
2065DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2066DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2067DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2068DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
2069DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2070DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
2071DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2072DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
2073 lu_result_sent == 0
2074- MS sends Authen Response with too short SRES data, auth is thwarted.
2075 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
2076DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
2077DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
2078DMM IMSI:901700000004620: MM AUTHENTICATION RESPONSE: l3 length invalid: 5
2079DMM IMSI:901700000004620: MM AUTHENTICATION RESPONSE: invalid: parsing GSM AKA Auth Response failed with rc=-22; dispatching zero length SRES/RES to trigger failure
2080DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = )
2081DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01002082DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: (0 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01002083DVLR SUBSCR(IMSI:901700000004620) AUTH SRES/RES missing
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002084DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
2085DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
2086DVLR GSUP tx: 0b010809710000004026f0
2087GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000004026f0
2088DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2089DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000004620)
2090DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
2091DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Deallocated
2092DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
2093- sending LU Reject for IMSI:901700000004620, cause 3
2094DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
2095DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
2096DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
2097DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
2098DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
2099DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2100DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2101DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
2102DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
2103DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
2104DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
2105DMM msc_subscr_conn_close(vsub=IMSI:901700000004620, cause=2): no conn fsm, releasing directly without release event.
2106- BSSAP Clear --RAN_GERAN_A--> MS
2107DREF IMSI:901700000004620: MSC conn use - fsm == 1 (0x2)
2108DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
2109DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
2110DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
2111DRLL subscr IMSI:901700000004620: Freeing subscriber connection
2112DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
2113DREF freeing VLR subscr IMSI:901700000004620
2114 lu_result_sent == 2
2115 llist_count(&net->subscr_conns) == 0
2116===== test_wrong_sres_length: SUCCESS
2117
2118full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002119talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002120
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002121full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002122talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002123