blob: b75ecc221d4b13b6247e5074b7814184749493e6 [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_ciph
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+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 lu_result_sent == 0
50 auth_request_sent == 1
51- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +010052 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +010053DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010054DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010055DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
56DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +010057DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010058DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
59DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
60DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
61DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
62DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
63DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
64DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
65DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
66DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +010067DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +010068DMM -> CIPHER MODE COMMAND IMSI:901700000004620
69- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
70- ...perm algo: 2
71- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010072DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010073DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010074DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010075 lu_result_sent == 0
76- needs ciph, not yet accepted
77msc_subscr_conn_is_accepted() == false
78 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +010079DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
80DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
81DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
82DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
83DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
84DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +010085DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
86DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010087 lu_result_sent == 0
88- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +010089 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010090DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
91DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
92DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
93DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
94DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
95DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
96DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
97DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
98DVLR GSUP tx: 04010809710000004026f0
99GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
100DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
101 lu_result_sent == 0
102- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
103<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
104DVLR GSUP rx 17: 10010809710000004026f00804036470f1
105DREF VLR subscr IMSI:901700000004620 usage increases to: 2
106DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100107DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100108DVLR GSUP tx: 12010809710000004026f0
109GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
110DREF VLR subscr MSISDN:46071 usage decreases to: 1
111<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
112 lu_result_sent == 0
113- HLR also sends GSUP _UPDATE_LOCATION_RESULT
114<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
115DVLR GSUP rx 11: 06010809710000004026f0
116DREF VLR subscr MSISDN:46071 usage increases to: 2
117DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
118DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
119DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
120DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
121DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
122DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
123DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
124DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
125DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
126DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
127DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
128DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
129DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
130DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
131DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
132DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
133DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
134DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
135DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
136DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
137DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
138DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
139- sending LU Accept for MSISDN:46071
140DREF VLR subscr MSISDN:46071 usage increases to: 3
141DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
142DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
143DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
144DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
145DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
146DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
147DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200148DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
149DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
150DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100151DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
152DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200153DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
154DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100155DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
156DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
157DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
158DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
159DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
160DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200161- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100162DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100163DRLL subscr MSISDN:46071: Freeing subscriber connection
164DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200165DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
166DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100167DREF VLR subscr MSISDN:46071 usage decreases to: 1
168<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +0200169 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100170- LU was successful, and the conn has already been closed
171 lu_result_sent == 1
172 llist_count(&net->subscr_conns) == 0
173---
174- 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 +0100175 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100176 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100177DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100178DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100179DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100180DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200181DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
182DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
183DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100184DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
185DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
186DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
187DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
188DREF VLR subscr MSISDN:46071 usage increases to: 2
189DREF VLR subscr MSISDN:46071 usage increases to: 3
190DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
191DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
192DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
193DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
194DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
195DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100196DVLR 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 +0100197- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
198- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
199- ...expecting sres=20bde240
200DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100201DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100202DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100203 auth_request_sent == 1
204 cm_service_result_sent == 0
205- needs auth, not yet accepted
206msc_subscr_conn_is_accepted() == false
207 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100208DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
209DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
210DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
211DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
212DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
213DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100214DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
215DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100216- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100217 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100218DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100219DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100220DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
221DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100222DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100223DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
224DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
225DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
226DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
227DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
228DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
229DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
230DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
231DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
232DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100233DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100234DMM -> CIPHER MODE COMMAND MSISDN:46071
235DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
236- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
237- ...perm algo: 2
238- ...key: 07fa7502e07e1c00
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100239DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100240DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100241DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100242 cm_service_result_sent == 0
243 cipher_mode_cmd_sent == 1
244- needs ciph, not yet accepted
245msc_subscr_conn_is_accepted() == false
246 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100247DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
248DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
249DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
250DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
251DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
252DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100253DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
254DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100255- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100256 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100257DRR MSISDN:46071: CIPHERING MODE COMPLETE
258DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
259DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
260DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
261DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
262DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
263DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
264DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
265DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
266DVLR 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 +0200267DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
268DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
269DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
270DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100271DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
272DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100273 cm_service_result_sent == 0
274- a USSD request is serviced
275 expecting USSD:
276 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100277 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100278DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100279DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
280DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200281DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
282DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100283DMM USSD: Own number requested
284DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200285DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100286- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100287- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100288DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
289DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200290DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
291DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100292DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
293DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
294DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
295DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
296DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200297- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100298DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200299DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
300DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100301DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100302DRLL subscr MSISDN:46071: Freeing subscriber connection
303DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200304 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100305- all requests serviced, conn has been released
306 llist_count(&net->subscr_conns) == 0
307---
308- an SMS is sent, MS is paged
309DREF VLR subscr MSISDN:46071 usage increases to: 2
310 llist_count(&vsub->cs.requests) == 0
311DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200312DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100313 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200314 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100315DREF VLR subscr MSISDN:46071 usage increases to: 4
316 llist_count(&vsub->cs.requests) == 1
317DREF VLR subscr MSISDN:46071 usage decreases to: 3
318 paging_sent == 1
319 paging_stopped == 0
320- the subscriber and its pending request should remain
321DREF VLR subscr MSISDN:46071 usage increases to: 4
322 llist_count(&vsub->cs.requests) == 1
323DREF VLR subscr MSISDN:46071 usage decreases to: 3
324- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100325 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100326 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100327DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100328DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100329DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100330DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200331DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
332DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
333DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100334DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
335DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
336DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
337DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
338DREF VLR subscr MSISDN:46071 usage increases to: 4
339DREF VLR subscr MSISDN:46071 usage increases to: 5
340DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
341DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
342DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
343DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
344DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
345DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100346DVLR 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 +0100347- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
348- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
349- ...expecting sres=a29514ae
350DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100351DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100352DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100353 auth_request_sent == 1
354- needs auth, not yet accepted
355msc_subscr_conn_is_accepted() == false
356 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100357DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
358DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
359DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
360DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
361DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
362DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100363DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
364DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100365- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100366 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100367DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100368DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100369DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
370DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100371DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100372DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
373DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
374DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
375DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
376DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
377DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
378DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
379DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
380DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
381DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100382DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100383DMM -> CIPHER MODE COMMAND MSISDN:46071
384DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
385- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
386- ...perm algo: 2
387- ...key: e2b234f807886400
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100388DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100389DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100390DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100391 cipher_mode_cmd_sent == 1
392- needs ciph, not yet accepted
393msc_subscr_conn_is_accepted() == false
394 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100395DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
396DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
397DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
398DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
399DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
400DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100401DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
402DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100403- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100404 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100405DRR MSISDN:46071: CIPHERING MODE COMPLETE
406DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
407DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
408DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
409DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
410DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
411DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
412DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
413DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
414DVLR 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 +0200415DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
416DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
417DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
418DPAG Paging success for MSISDN:46071 (event=0)
419DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100420DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100421DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100422DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x14)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200423DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100424- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100425- DTAP matches expected message
426DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100427DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
428DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100429 dtap_tx_confirmed == 1
430 paging_stopped == 1
431- SMS was delivered, no requests pending for subscr
432DREF VLR subscr MSISDN:46071 usage increases to: 5
433 llist_count(&vsub->cs.requests) == 0
434DREF VLR subscr MSISDN:46071 usage decreases to: 4
435- conn is still open to wait for SMS ack dance
436 llist_count(&net->subscr_conns) == 1
437- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100438 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100439DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100440DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200441DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
442DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100443DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
444DMM 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 +0100445DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100446 llist_count(&net->subscr_conns) == 1
447- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100448 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100449DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100450DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200451DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
452DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100453- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100454- DTAP matches expected message
455DREF VLR subscr MSISDN:46071 usage decreases to: 3
456DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100457DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100458DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
459DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200460DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
461DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100462DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
463DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
464DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
465DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
466DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200467- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100468DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200469DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
470DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100471DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100472DRLL subscr MSISDN:46071: Freeing subscriber connection
473DREF VLR subscr MSISDN:46071 usage decreases to: 1
474 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200475 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100476- SMS is done, conn is gone
477 llist_count(&net->subscr_conns) == 0
478---
479- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100480 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100481 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100482DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100483DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100484DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
485DREF VLR subscr MSISDN:46071 usage increases to: 2
486DMM IMSI DETACH for MSISDN:46071
487DREF VLR subscr MSISDN:46071 usage decreases to: 1
488DREF VLR subscr MSISDN:46071 usage decreases to: 0
489DREF freeing VLR subscr MSISDN:46071
490DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200491- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100492DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100493DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200494 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100495 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100496===== test_ciph: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100497
498full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200499talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100500
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100501===== test_ciph_tmsi
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100502- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100503 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100504 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100505DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100506DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100507DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200508DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
509DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
510DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100511DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100512DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100513DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
514DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
515DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
516DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
517DREF VLR subscr unknown usage increases to: 1
518DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
519DVLR New subscr, IMSI: 901700000004620
520DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200521DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100522DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
523DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
524DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
525DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
526DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
527DVLR GSUP tx: 08010809710000004026f0
528GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
529DVLR 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 +0100530DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100531DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100532 lu_result_sent == 0
533- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
534<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
535DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
536DREF VLR subscr IMSI:901700000004620 usage increases to: 2
537DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
538DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
539DVLR 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 +0100540DVLR 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 +0100541- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
542- ...rand=585df1ae287f6e273dce07090d61320b
543- ...expecting sres=2d8b2c3e
544DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
545<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
546 auth_request_sent == 1
547 lu_result_sent == 0
548- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100549 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100550DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100551DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100552DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
553DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100554DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100555DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
556DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
557DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
558DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
559DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
560DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
561DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
562DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
563DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +0100564DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100565DMM -> CIPHER MODE COMMAND IMSI:901700000004620
566- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
567- ...perm algo: 2
568- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100569DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100570DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100571DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100572 lu_result_sent == 0
573 auth_request_sent == 1
574- needs ciph, not yet accepted
575msc_subscr_conn_is_accepted() == false
576 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100577DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
578DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
579DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
580DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
581DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
582DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100583DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
584DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100585 lu_result_sent == 0
586- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100587 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100588DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
589DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
590DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
591DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
592DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
593DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
594DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
595DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
596DVLR GSUP tx: 04010809710000004026f0
597GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
598DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
599 lu_result_sent == 0
600- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
601<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
602DVLR GSUP rx 17: 10010809710000004026f00804036470f1
603DREF VLR subscr IMSI:901700000004620 usage increases to: 2
604DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100605DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100606DVLR GSUP tx: 12010809710000004026f0
607GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
608DREF VLR subscr MSISDN:46071 usage decreases to: 1
609<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
610 lu_result_sent == 0
611- HLR also sends GSUP _UPDATE_LOCATION_RESULT
612<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
613DVLR GSUP rx 11: 06010809710000004026f0
614DREF VLR subscr MSISDN:46071 usage increases to: 2
615DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
616DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
617DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
618DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
619DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
620DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
621DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
622DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
623DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
624DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
625DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
626DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
627DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
628DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
629DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
630DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
631DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
632DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
633DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
634DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
635DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
636DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
637DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
638DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
639- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
640DREF VLR subscr MSISDN:46071 usage decreases to: 1
641<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
642- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
643 llist_count(&net->subscr_conns) == 1
644 lu_result_sent == 1
645msc_subscr_conn_is_accepted() == false
646 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100647DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
648DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
649DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
650DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
651DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
652DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100653DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
654DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100655- even though the TMSI is not acked, we can already find the subscr with it
656DREF VLR subscr MSISDN:46071 usage increases to: 2
657 vsub != NULL == 1
658 strcmp(vsub->imsi, imsi) == 0
659 vsub->tmsi_new == 0x03020100
660 vsub->tmsi == 0xffffffff
661DREF VLR subscr MSISDN:46071 usage decreases to: 1
662- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100663 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100664DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100665DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100666DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
667DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
668DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
669DREF VLR subscr MSISDN:46071 usage increases to: 2
670DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
671DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
672DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
673DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
674DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
675DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
676DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200677DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
678DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
679DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100680DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
681DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200682DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
683DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100684DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
685DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
686DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
687DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
688DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
689DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200690- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100691DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200692DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
693DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100694DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100695DRLL subscr MSISDN:46071: Freeing subscriber connection
696DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200697 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100698- LU was successful, and the conn has already been closed
699 llist_count(&net->subscr_conns) == 0
700- Subscriber has the new TMSI
701DREF VLR subscr MSISDN:46071 usage increases to: 2
702 vsub != NULL == 1
703 strcmp(vsub->imsi, imsi) == 0
704 vsub->tmsi_new == 0xffffffff
705 vsub->tmsi == 0x03020100
706DREF VLR subscr MSISDN:46071 usage decreases to: 1
707---
708- 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 +0100709 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100710 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100711DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100712DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100713DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100714DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200715DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
716DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
717DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100718DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
719DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
720DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
721DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
722DREF VLR subscr MSISDN:46071 usage increases to: 2
723DREF VLR subscr MSISDN:46071 usage increases to: 3
724DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
725DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
726DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
727DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
728DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
729DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100730DVLR 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 +0100731- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
732- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
733- ...expecting sres=20bde240
734DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100735DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100736DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100737 auth_request_sent == 1
738 cm_service_result_sent == 0
739- needs auth, not yet accepted
740msc_subscr_conn_is_accepted() == false
741 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100742DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
743DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
744DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
745DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
746DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
747DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100748DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
749DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100750- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100751 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100752DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100753DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100754DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
755DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100756DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100757DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
758DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
759DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
760DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
761DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
762DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
763DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
764DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
765DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
766DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100767DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100768DMM -> CIPHER MODE COMMAND MSISDN:46071
769DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
770- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
771- ...perm algo: 2
772- ...key: 07fa7502e07e1c00
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100773DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100774DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100775DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100776 cm_service_result_sent == 0
777 cipher_mode_cmd_sent == 1
778- needs ciph, not yet accepted
779msc_subscr_conn_is_accepted() == false
780 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100781DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
782DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
783DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
784DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
785DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
786DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100787DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
788DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100789- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100790 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100791DRR MSISDN:46071: CIPHERING MODE COMPLETE
792DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
793DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
794DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
795DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
796DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
797DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
798DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
799DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
800DVLR 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 +0200801DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
802DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
803DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
804DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100805DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
806DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100807 cm_service_result_sent == 0
808- a USSD request is serviced
809 expecting USSD:
810 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100811 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100812DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100813DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
814DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200815DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
816DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100817DMM USSD: Own number requested
818DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200819DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100820- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100821- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100822DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
823DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200824DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
825DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100826DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
827DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
828DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
829DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
830DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200831- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100832DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200833DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
834DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100835DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100836DRLL subscr MSISDN:46071: Freeing subscriber connection
837DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200838 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100839- all requests serviced, conn has been released
840 llist_count(&net->subscr_conns) == 0
841---
842- an SMS is sent, MS is paged
843DREF VLR subscr MSISDN:46071 usage increases to: 2
844 llist_count(&vsub->cs.requests) == 0
845DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200846DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100847 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100848 paging_expecting_tmsi == 0x03020100
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100849DREF VLR subscr MSISDN:46071 usage increases to: 4
850 llist_count(&vsub->cs.requests) == 1
851DREF VLR subscr MSISDN:46071 usage decreases to: 3
852 paging_sent == 1
853 paging_stopped == 0
854- the subscriber and its pending request should remain
855DREF VLR subscr MSISDN:46071 usage increases to: 4
856 llist_count(&vsub->cs.requests) == 1
857DREF VLR subscr MSISDN:46071 usage decreases to: 3
858- MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100859 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100860 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100861DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100862DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100863DRR PAGING RESPONSE: MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100864DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200865DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
866DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
867DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100868DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
869DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
870DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
871DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
872DREF VLR subscr MSISDN:46071 usage increases to: 4
873DREF VLR subscr MSISDN:46071 usage increases to: 5
874DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
875DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
876DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
877DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
878DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
879DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100880DVLR 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 +0100881- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
882- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
883- ...expecting sres=a29514ae
884DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100885DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100886DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100887 auth_request_sent == 1
888- needs auth, not yet accepted
889msc_subscr_conn_is_accepted() == false
890 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100891DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
892DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
893DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
894DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
895DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
896DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100897DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
898DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100899- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100900 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100901DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100902DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100903DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
904DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100905DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100906DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
907DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
908DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
909DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
910DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
911DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
912DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
913DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
914DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
915DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100916DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100917DMM -> CIPHER MODE COMMAND MSISDN:46071
918DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
919- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
920- ...perm algo: 2
921- ...key: e2b234f807886400
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100922DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100923DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100924DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100925 cipher_mode_cmd_sent == 1
926- needs ciph, not yet accepted
927msc_subscr_conn_is_accepted() == false
928 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100929DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
930DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
931DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
932DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
933DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
934DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100935DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
936DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100937- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100938 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100939DRR MSISDN:46071: CIPHERING MODE COMPLETE
940DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
941DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
942DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
943DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
944DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
945DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
946DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
947DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
948DVLR 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 +0200949DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
950DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
951DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
952DPAG Paging success for MSISDN:46071 (event=0)
953DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100954DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100955DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100956DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x14)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200957DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100958- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100959- DTAP matches expected message
960DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100961DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
962DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100963 dtap_tx_confirmed == 1
964 paging_stopped == 1
965- SMS was delivered, no requests pending for subscr
966DREF VLR subscr MSISDN:46071 usage increases to: 5
967 llist_count(&vsub->cs.requests) == 0
968DREF VLR subscr MSISDN:46071 usage decreases to: 4
969- conn is still open to wait for SMS ack dance
970 llist_count(&net->subscr_conns) == 1
971- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100972 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100973DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100974DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200975DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
976DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100977DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
978DMM 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 +0100979DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100980 llist_count(&net->subscr_conns) == 1
981- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100982 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100983DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100984DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200985DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
986DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100987- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100988- DTAP matches expected message
989DREF VLR subscr MSISDN:46071 usage decreases to: 3
990DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100991DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100992DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
993DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200994DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
995DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100996DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
997DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
998DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
999DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
1000DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001001- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001002DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001003DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
1004DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001005DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001006DRLL subscr MSISDN:46071: Freeing subscriber connection
1007DREF VLR subscr MSISDN:46071 usage decreases to: 1
1008 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001009 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001010- SMS is done, conn is gone
1011 llist_count(&net->subscr_conns) == 0
1012---
1013- subscriber detaches, using TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001014 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001015 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001016DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001017DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001018DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1019DREF VLR subscr MSISDN:46071 usage increases to: 2
1020DMM IMSI DETACH for MSISDN:46071
1021DREF VLR subscr MSISDN:46071 usage decreases to: 1
1022DREF VLR subscr MSISDN:46071 usage decreases to: 0
1023DREF freeing VLR subscr MSISDN:46071
1024DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001025- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001026DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001027DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001028 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001029 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001030===== test_ciph_tmsi: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001031
1032full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001033talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001034
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001035===== test_ciph_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001036- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001037 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001038 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001039DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001040DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001041DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001042DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1043DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1044DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001045DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001046DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001047DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1048DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1049DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
1050DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1051DREF VLR subscr unknown usage increases to: 1
1052DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1053DVLR New subscr, IMSI: 901700000004620
1054DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001055DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001056DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1057DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1058DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1059DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1060DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1061DVLR GSUP tx: 08010809710000004026f0
1062GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1063DVLR 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 +01001064DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001065DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001066 lu_result_sent == 0
1067- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1068<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1069DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1070DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1071DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1072DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1073DVLR 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 +01001074DVLR 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 +01001075- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1076- ...rand=585df1ae287f6e273dce07090d61320b
1077- ...expecting sres=2d8b2c3e
1078DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1079<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1080 auth_request_sent == 1
1081 lu_result_sent == 0
1082- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001083 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001084DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001085DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001086DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1087DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001088DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001089DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1090DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1091DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1092DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1093DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1094DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1095DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1096DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1097DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001098DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001099DMM -> CIPHER MODE COMMAND IMSI:901700000004620
1100- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
1101- ...perm algo: 2
1102- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001103DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001104DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001105DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001106 lu_result_sent == 0
1107- needs ciph, not yet accepted
1108msc_subscr_conn_is_accepted() == false
1109 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001110DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1111DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1112DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1113DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1114DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1115DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001116DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1117DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001118 lu_result_sent == 0
1119- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001120 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001121DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
1122DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1123DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1124DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1125DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1126DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1127DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1128DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1129DVLR GSUP tx: 04010809710000004026f0
1130GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1131DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1132 lu_result_sent == 0
1133- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1134<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1135DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1136DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1137DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001138DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001139DVLR GSUP tx: 12010809710000004026f0
1140GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1141DREF VLR subscr MSISDN:46071 usage decreases to: 1
1142<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1143 lu_result_sent == 0
1144- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1145<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1146DVLR GSUP rx 11: 06010809710000004026f0
1147DREF VLR subscr MSISDN:46071 usage increases to: 2
1148DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1149DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1150DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1151DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1152DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1153DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1154DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1155DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1156DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1157DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1158DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1159DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1160DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1161DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1162DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1163DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1164DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1165DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1166DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1167DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1168DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1169DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1170DVLR 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 +02001171DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001172- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001173- DTAP matches expected message
1174DREF VLR subscr MSISDN:46071 usage decreases to: 1
1175<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1176- We will only do business when the IMEI is known
1177 llist_count(&net->subscr_conns) == 1
1178DREF VLR subscr MSISDN:46071 usage increases to: 2
1179 vsub->imei[0] == 0
1180DREF VLR subscr MSISDN:46071 usage decreases to: 1
1181msc_subscr_conn_is_accepted() == false
1182 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001183DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1184DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1185DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1186DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1187DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1188DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001189DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1190DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001191- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001192 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001193DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001194DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001195DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1196DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001197DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1198DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1199- sending LU Accept for MSISDN:46071
1200DREF VLR subscr MSISDN:46071 usage increases to: 2
1201DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
1202DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1203DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1204DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1205DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1206DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1207DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001208DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1209DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1210DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001211DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1212DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001213DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1214DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001215DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1216DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1217DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1218DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1219DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1220DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001221- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001222DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001223DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1224DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001225DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001226DRLL subscr MSISDN:46071: Freeing subscriber connection
1227DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001228 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001229- LU was successful, and the conn has already been closed
1230 lu_result_sent == 1
1231 llist_count(&net->subscr_conns) == 0
1232- Subscriber has the IMEI
1233DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001234 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001235DREF VLR subscr MSISDN:46071 usage decreases to: 1
1236---
1237- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001238 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001239 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001240DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001241DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001242DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1243DREF VLR subscr MSISDN:46071 usage increases to: 2
1244DMM IMSI DETACH for MSISDN:46071
1245DREF VLR subscr MSISDN:46071 usage decreases to: 1
1246DREF VLR subscr MSISDN:46071 usage decreases to: 0
1247DREF freeing VLR subscr MSISDN:46071
1248DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001249- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001250DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001251DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001252 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001253 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001254===== test_ciph_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001255
1256full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001257talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001258
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001259===== test_ciph_imeisv
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001260- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001261 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001262 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001263DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001264DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001265DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001266DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1267DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1268DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001269DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001270DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001271DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1272DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1273DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
1274DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1275DREF VLR subscr unknown usage increases to: 1
1276DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1277DVLR New subscr, IMSI: 901700000004620
1278DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001279DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001280DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1281DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1282DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1283DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1284DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1285DVLR GSUP tx: 08010809710000004026f0
1286GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1287DVLR 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 +01001288DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001289DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001290 lu_result_sent == 0
1291- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1292<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1293DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1294DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1295DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1296DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1297DVLR 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 +01001298DVLR 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 +01001299- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1300- ...rand=585df1ae287f6e273dce07090d61320b
1301- ...expecting sres=2d8b2c3e
1302DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1303<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1304 auth_request_sent == 1
1305 lu_result_sent == 0
1306- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001307 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001308DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001309DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001310DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1311DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001312DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001313DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1314DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1315DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1316DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1317DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1318DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1319DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1320DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1321DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001322DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001323DMM -> CIPHER MODE COMMAND IMSI:901700000004620
1324- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=1
1325- ...perm algo: 2
1326- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001327DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001328DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001329DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001330 cipher_mode_cmd_sent == 1
1331 cipher_mode_cmd_sent_with_imeisv == 1
1332 lu_result_sent == 0
1333- needs ciph, not yet accepted
1334msc_subscr_conn_is_accepted() == false
1335 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001336DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1337DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1338DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1339DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1340DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1341DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001342DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1343DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001344 lu_result_sent == 0
1345DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1346 vsub->imeisv[0] == 0
1347DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1348- MS sends Ciphering Mode Complete with IMEISV, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001349 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001350DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
1351DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001352DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: got IMEISV: 4234234234234275F
1353DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=4234234234234275
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001354DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1355DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1356DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1357DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1358DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1359DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1360DVLR GSUP tx: 04010809710000004026f0
1361GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1362DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1363 lu_result_sent == 0
1364- Subscriber has the IMEISV
1365DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001366 strcmp(vsub->imeisv, "4234234234234275") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001367DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1368msc_subscr_conn_is_accepted() == false
1369 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001370DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1371DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1372DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1373DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1374DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1375DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001376DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1377DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001378- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1379<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1380DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1381DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1382DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001383DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001384DVLR GSUP tx: 12010809710000004026f0
1385GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1386DREF VLR subscr MSISDN:46071 usage decreases to: 1
1387<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1388 lu_result_sent == 0
1389- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1390<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1391DVLR GSUP rx 11: 06010809710000004026f0
1392DREF VLR subscr MSISDN:46071 usage increases to: 2
1393DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1394DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1395DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1396DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1397DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1398DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1399DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1400DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1401DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1402DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1403DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1404DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1405DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1406DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1407DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1408DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1409DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1410DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1411DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1412DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1413DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1414DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1415- sending LU Accept for MSISDN:46071
1416DREF VLR subscr MSISDN:46071 usage increases to: 3
1417DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1418DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1419DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1420DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1421DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1422DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1423DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001424DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1425DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1426DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001427DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1428DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001429DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1430DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001431DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1432DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1433DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1434DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1435DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1436DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001437- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001438DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001439DRLL subscr MSISDN:46071: Freeing subscriber connection
1440DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001441DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1442DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001443DREF VLR subscr MSISDN:46071 usage decreases to: 1
1444<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +02001445 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001446- LU was successful, and the conn has already been closed
1447 lu_result_sent == 1
1448 llist_count(&net->subscr_conns) == 0
1449---
1450- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001451 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001452 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001453DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001454DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001455DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1456DREF VLR subscr MSISDN:46071 usage increases to: 2
1457DMM IMSI DETACH for MSISDN:46071
1458DREF VLR subscr MSISDN:46071 usage decreases to: 1
1459DREF VLR subscr MSISDN:46071 usage decreases to: 0
1460DREF freeing VLR subscr MSISDN:46071
1461DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001462- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001463DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001464DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001465 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001466 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001467===== test_ciph_imeisv: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001468
1469full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001470talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001471
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001472===== test_ciph_tmsi_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001473- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001474 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001475 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001476DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001477DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001478DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001479DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1480DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1481DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001482DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001483DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001484DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1485DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1486DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
1487DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1488DREF VLR subscr unknown usage increases to: 1
1489DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1490DVLR New subscr, IMSI: 901700000004620
1491DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001492DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001493DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1494DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1495DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1496DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1497DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1498DVLR GSUP tx: 08010809710000004026f0
1499GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1500DVLR 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 +01001501DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001502DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001503 lu_result_sent == 0
1504- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1505<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1506DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1507DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1508DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1509DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1510DVLR 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 +01001511DVLR 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 +01001512- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1513- ...rand=585df1ae287f6e273dce07090d61320b
1514- ...expecting sres=2d8b2c3e
1515DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1516<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1517 auth_request_sent == 1
1518 lu_result_sent == 0
1519- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001520 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001521DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001522DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001523DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1524DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001525DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001526DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1527DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1528DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1529DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1530DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1531DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1532DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1533DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1534DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001535DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001536DMM -> CIPHER MODE COMMAND IMSI:901700000004620
1537- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
1538- ...perm algo: 2
1539- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001540DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001541DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001542DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001543 lu_result_sent == 0
1544- needs ciph, not yet accepted
1545msc_subscr_conn_is_accepted() == false
1546 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001547DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1548DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1549DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1550DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1551DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1552DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001553DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1554DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001555 lu_result_sent == 0
1556- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001557 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001558DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
1559DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1560DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1561DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1562DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1563DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1564DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1565DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1566DVLR GSUP tx: 04010809710000004026f0
1567GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1568DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1569 lu_result_sent == 0
1570- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1571<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1572DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1573DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1574DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001575DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001576DVLR GSUP tx: 12010809710000004026f0
1577GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1578DREF VLR subscr MSISDN:46071 usage decreases to: 1
1579<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1580 lu_result_sent == 0
1581- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1582<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1583DVLR GSUP rx 11: 06010809710000004026f0
1584DREF VLR subscr MSISDN:46071 usage increases to: 2
1585DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1586DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1587DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1588DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1589DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1590DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1591DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1592DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1593DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1594DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1595DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1596DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1597DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1598DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1599DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1600DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1601DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1602DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1603DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1604DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1605DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1606DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1607DVLR 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 +02001608DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001609- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001610- DTAP matches expected message
1611DREF VLR subscr MSISDN:46071 usage decreases to: 1
1612<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1613- We will only do business when the IMEI is known
1614 llist_count(&net->subscr_conns) == 1
1615DREF VLR subscr MSISDN:46071 usage increases to: 2
1616 vsub->imei[0] == 0
1617DREF VLR subscr MSISDN:46071 usage decreases to: 1
1618msc_subscr_conn_is_accepted() == false
1619 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001620DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1621DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1622DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1623DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1624DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1625DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001626DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1627DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001628- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001629 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001630DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001631DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001632DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1633DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001634DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1635DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1636DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
1637DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1638- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001639DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001640DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001641- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1642 llist_count(&net->subscr_conns) == 1
1643 lu_result_sent == 1
1644msc_subscr_conn_is_accepted() == false
1645 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001646DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1647DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1648DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1649DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1650DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1651DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001652DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1653DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001654- even though the TMSI is not acked, we can already find the subscr with it
1655DREF VLR subscr MSISDN:46071 usage increases to: 2
1656 vsub != NULL == 1
1657 strcmp(vsub->imsi, imsi) == 0
1658 vsub->tmsi_new == 0x03020100
1659 vsub->tmsi == 0xffffffff
1660DREF VLR subscr MSISDN:46071 usage decreases to: 1
1661- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001662 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001663DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001664DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001665DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1666DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1667DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1668DREF VLR subscr MSISDN:46071 usage increases to: 2
1669DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1670DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1671DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1672DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1673DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1674DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1675DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001676DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1677DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1678DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001679DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1680DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001681DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1682DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001683DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1684DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1685DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1686DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1687DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1688DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001689- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001690DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001691DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1692DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001693DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001694DRLL subscr MSISDN:46071: Freeing subscriber connection
1695DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001696 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001697- LU was successful, and the conn has already been closed
1698 llist_count(&net->subscr_conns) == 0
1699- Subscriber has the IMEI and TMSI
1700DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001701 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001702 vsub->tmsi == 0x03020100
1703DREF VLR subscr MSISDN:46071 usage decreases to: 1
1704---
1705- subscriber detaches, using TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001706 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001707 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001708DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001709DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001710DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1711DREF VLR subscr MSISDN:46071 usage increases to: 2
1712DMM IMSI DETACH for MSISDN:46071
1713DREF VLR subscr MSISDN:46071 usage decreases to: 1
1714DREF VLR subscr MSISDN:46071 usage decreases to: 0
1715DREF freeing VLR subscr MSISDN:46071
1716DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001717- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001718DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001719DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001720 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001721 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001722===== test_ciph_tmsi_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001723
1724full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001725talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001726
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001727===== test_gsm_ciph_in_umts_env
1728- Location Update request causes a GSUP Send Auth Info request to HLR
1729 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1730 new conn
1731DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1732DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1733DREF unknown: MSC conn use + fsm == 2 (0x5)
1734DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1735DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1736DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1737DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1738DMM LU/new-LAC: 0/23
1739DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1740DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1741DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth+Ciph
1742DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1743DREF VLR subscr unknown usage increases to: 1
1744DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1745DVLR New subscr, IMSI: 901700000010650
1746DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1747DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1748DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1749DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1750DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1751DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1752DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1753DVLR GSUP tx: 08010809710000000156f0
1754GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1755DVLR 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 +01001756DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001757DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1758 lu_result_sent == 0
1759- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends *UMTS AKA* Auth Req to MS
1760<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220104ac8d1cd1a51937597ca1016fe69a0fa2104dacc4b2622087a75f0ac9b84440023103747da4e31545baa2db59e500bdae04724108544d35b945ccba01a7f1293575291c325102d837d2b0d6f00004b282d5acf23428d270837527064741f8ddb03622010b2661531b97b12c5a2edc21a0ed16fc521042fb4cfad2208da149b11d473f40023103fe013b1a428ea737c37f8f0288c8edf2410f275438c02b97e4d6f639dddda3d10b9251078cdd96c60840000322f421b3bb778b12708ed3ebf9cb6ea48ed0362201054d8f19778056666b41c8c25e52eb60c21040ff61e0f220826ec67fad307300023102868b0922c652616f1c975e3eaf7943a24106a84a20b1bc13ec9840466406d2dd91e251053f3e5632b3d00008865dd54d49663f2270886e848a9e7ad8cd5036220101f05607ff9c8984f46ad97f8c9a94982210491a36e3d22085d84421884fdcc0023102171fef54b81e30c83a598a5e44f634c2410f02d088697509827565b46938fece21125101b43bbf9815e00001cb9b2a9f6b8a77c2708373e67d62e719c510362201080d89a58a2a41050918caf68a4e93c642104a319f5f12208883df2b8672930002310fa5d70f929ff298efb160413698dc1072410ae9a3d8ce70ce13bac297bdb91cd6c6825105c0dc2eeaefa0000396882a1fe2cf80b270865ab1cad216bfe87
1761DVLR GSUP rx 511: 0a010809710000000156f0036220104ac8d1cd1a51937597ca1016fe69a0fa2104dacc4b2622087a75f0ac9b84440023103747da4e31545baa2db59e500bdae04724108544d35b945ccba01a7f1293575291c325102d837d2b0d6f00004b282d5acf23428d270837527064741f8ddb03622010b2661531b97b12c5a2edc21a0ed16fc521042fb4cfad2208da149b11d473f40023103fe013b1a428ea737c37f8f0288c8edf2410f275438c02b97e4d6f639dddda3d10b9251078cdd96c60840000322f421b3bb778b12708ed3ebf9cb6ea48ed0362201054d8f19778056666b41c8c25e52eb60c21040ff61e0f220826ec67fad307300023102868b0922c652616f1c975e3eaf7943a24106a84a20b1bc13ec9840466406d2dd91e251053f3e5632b3d00008865dd54d49663f2270886e848a9e7ad8cd5036220101f05607ff9c8984f46ad97f8c9a94982210491a36e3d22085d84421884fdcc0023102171fef54b81e30c83a598a5e44f634c2410f02d088697509827565b46938fece21125101b43bbf9815e00001cb9b2a9f6b8a77c2708373e67d62e719c510362201080d89a58a2a41050918caf68a4e93c642104a319f5f12208883df2b8672930002310fa5d70f929ff298efb160413698dc1072410ae9a3d8ce70ce13bac297bdb91cd6c6825105c0dc2eeaefa0000396882a1fe2cf80b270865ab1cad216bfe87
1762DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1763DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1764DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1765DVLR 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 +01001766DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001767- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1768- ...rand=4ac8d1cd1a51937597ca1016fe69a0fa
1769- ...autn=2d837d2b0d6f00004b282d5acf23428d
1770- ...expecting res=37527064741f8ddb
1771DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1772<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1773 auth_request_sent == 1
1774 lu_result_sent == 0
1775- MS sends *GSM AKA* Authen Response, VLR accepts and sends Ciphering Mode Command to MS
1776 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1777DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1778DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1779DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = dacc4b26)
1780DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001781DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: dacc4b26 (4 bytes)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001782DVLR SUBSCR(IMSI:901700000010650) AUTH established GSM security context
1783DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1784DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1785DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1786DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1787DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1788DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1789DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1790DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1791DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
1792DMM -> CIPHER MODE COMMAND IMSI:901700000010650
1793- sending Ciphering Mode Command for IMSI:901700000010650: include_imeisv=0
1794- ...perm algo: 2
Neels Hofmeyr7795a192018-03-10 00:26:36 +01001795- ...key: 7a75f0ac9b844400
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001796DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001797DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001798DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
1799 lu_result_sent == 0
1800- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
1801 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
1802DRR IMSI:901700000010650: CIPHERING MODE COMPLETE
1803DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1804DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1805DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1806DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1807DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1808DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1809DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1810DVLR GSUP tx: 04010809710000000156f0
1811GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1812DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1813 lu_result_sent == 0
1814- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1815<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1816DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1817DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1818DVLR IMSI:901700000010650 has MSISDN:42342
1819DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1820DVLR GSUP tx: 12010809710000000156f0
1821GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1822DREF VLR subscr MSISDN:42342 usage decreases to: 1
1823<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1824 lu_result_sent == 0
1825- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1826<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1827DVLR GSUP rx 11: 06010809710000000156f0
1828DREF VLR subscr MSISDN:42342 usage increases to: 2
1829DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1830DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1831DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1832DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1833DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1834DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1835DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1836DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1837DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1838DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1839DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1840DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1841DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1842DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1843DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1844DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1845DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1846DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1847DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1848DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1849DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1850DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1851- sending LU Accept for MSISDN:42342
1852DREF VLR subscr MSISDN:42342 usage increases to: 3
1853DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1854DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1855DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1856DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1857DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1858DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1859DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1860DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1861DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1862DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001863DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1864DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001865DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1866DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1867DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1868DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1869DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1870DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1871DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1872DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1873- BSSAP Clear --RAN_GERAN_A--> MS
1874DREF MSISDN:42342: MSC conn use - fsm == 0 (0x0)
1875DRLL subscr MSISDN:42342: Freeing subscriber connection
1876DREF VLR subscr MSISDN:42342 usage decreases to: 2
1877DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1878DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1879DREF VLR subscr MSISDN:42342 usage decreases to: 1
1880<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1881 bssap_clear_sent == 1
1882- LU was successful, and the conn has already been closed
1883 lu_result_sent == 1
1884 llist_count(&net->subscr_conns) == 0
1885---
1886- after a while, a new conn sends a CM Service Request. VLR responds with *UMTS AKA* Auth Req, 2nd auth vector
1887 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
1888 new conn
1889DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1890DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
1891DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
1892DREF unknown: MSC conn use + fsm == 2 (0x5)
1893DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1894DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1895DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1896DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1897DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1898DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
1899DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1900DREF VLR subscr MSISDN:42342 usage increases to: 2
1901DREF VLR subscr MSISDN:42342 usage increases to: 3
1902DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1903DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1904DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1905DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1906DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1907DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001908DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001909- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1910- ...rand=b2661531b97b12c5a2edc21a0ed16fc5
1911- ...autn=78cdd96c60840000322f421b3bb778b1
1912- ...expecting res=ed3ebf9cb6ea48ed
1913DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001914DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001915DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
1916 cm_service_result_sent == 0
1917 auth_request_sent == 1
1918- needs auth, not yet accepted
1919msc_subscr_conn_is_accepted() == false
1920 requests shall be thwarted
1921DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1922DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1923DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1924DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1925DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1926DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
1927DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1928DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
1929- MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering
1930 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1931DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1932DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1933DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 2fb4cfad)
1934DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001935DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 2fb4cfad (4 bytes)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001936DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1937DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1938DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1939DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1940DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1941DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1942DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1943DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1944DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1945DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1946DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
1947DMM -> CIPHER MODE COMMAND MSISDN:42342
1948DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
1949- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
1950- ...perm algo: 2
Neels Hofmeyr7795a192018-03-10 00:26:36 +01001951- ...key: da149b11d473f400
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001952DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001953DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001954DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
1955 cm_service_result_sent == 0
1956 cipher_mode_cmd_sent == 1
1957- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
1958 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
1959DRR MSISDN:42342: CIPHERING MODE COMPLETE
1960DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1961DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
1962DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1963DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1964DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1965DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
1966DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1967DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
1968DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1969DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1970DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
1971DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1972DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001973DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1974DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001975 cm_service_result_sent == 0
1976- a USSD request is serviced
1977 expecting USSD:
1978 Your extension is 42342
1979 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
1980DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1981DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
1982DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
1983DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1984DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1985DMM USSD: Own number requested
1986DMM MSISDN:42342: MSISDN = 42342
1987DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
1988- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
1989- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001990DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1991DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001992DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1993DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1994DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1995DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1996DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1997DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1998DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1999- BSSAP Clear --RAN_GERAN_A--> MS
2000DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
2001DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
2002DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
2003DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
2004DRLL subscr MSISDN:42342: Freeing subscriber connection
2005DREF VLR subscr MSISDN:42342 usage decreases to: 1
2006 bssap_clear_sent == 1
2007- all requests serviced, conn has been released
2008 llist_count(&net->subscr_conns) == 0
2009---
2010- an SMS is sent, MS is paged
2011DREF VLR subscr MSISDN:42342 usage increases to: 2
2012 llist_count(&vsub->cs.requests) == 0
2013DREF VLR subscr MSISDN:42342 usage increases to: 3
2014DMM Subscriber MSISDN:42342 not paged yet, start paging.
2015 RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
2016 strcmp(paging_expecting_imsi, imsi) == 0
2017DREF VLR subscr MSISDN:42342 usage increases to: 4
2018 llist_count(&vsub->cs.requests) == 1
2019DREF VLR subscr MSISDN:42342 usage decreases to: 3
2020 paging_sent == 1
2021 paging_stopped == 0
2022- the subscriber and its pending request should remain
2023DREF VLR subscr MSISDN:42342 usage increases to: 4
2024 llist_count(&vsub->cs.requests) == 1
2025DREF VLR subscr MSISDN:42342 usage decreases to: 3
2026- MS replies with Paging Response, and VLR sends *UMTS AKA* Auth Request with third key
2027 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
2028 new conn
2029DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2030DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
2031DRR PAGING RESPONSE: MI(IMSI)=901700000010650
2032DREF unknown: MSC conn use + fsm == 2 (0x5)
2033DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
2034DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
2035DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
2036DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
2037DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
2038DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
2039DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
2040DREF VLR subscr MSISDN:42342 usage increases to: 4
2041DREF VLR subscr MSISDN:42342 usage increases to: 5
2042DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
2043DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
2044DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
2045DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
2046DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
2047DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01002048DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002049- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
2050- ...rand=54d8f19778056666b41c8c25e52eb60c
2051- ...autn=53f3e5632b3d00008865dd54d49663f2
2052- ...expecting res=86e848a9e7ad8cd5
2053DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002054DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002055DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
2056 auth_request_sent == 1
2057- needs auth, not yet accepted
2058msc_subscr_conn_is_accepted() == false
2059 requests shall be thwarted
2060DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2061DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2062DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2063DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
2064DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2065DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
2066DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2067DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
2068- MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering
2069 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
2070DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
2071DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
2072DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 0ff61e0f)
2073DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01002074DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 0ff61e0f (4 bytes)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002075DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
2076DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
2077DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
2078DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2079DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
2080DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
2081DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
2082DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
2083DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
2084DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
2085DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
2086DMM -> CIPHER MODE COMMAND MSISDN:42342
2087DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
2088- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
2089- ...perm algo: 2
Neels Hofmeyr7795a192018-03-10 00:26:36 +01002090- ...key: 26ec67fad3073000
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002091DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002092DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002093DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
2094 cipher_mode_cmd_sent == 1
2095- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
2096 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
2097DRR MSISDN:42342: CIPHERING MODE COMPLETE
2098DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
2099DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
2100DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
2101DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
2102DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
2103DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
2104DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
2105DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
2106DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
2107DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
2108DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
2109DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
2110DPAG Paging success for MSISDN:42342 (event=0)
2111DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01002112DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002113DREF VLR subscr MSISDN:42342 usage increases to: 5
2114DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x14)
2115DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
2116- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
2117- DTAP matches expected message
2118DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002119DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
2120DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002121 dtap_tx_confirmed == 1
2122 paging_stopped == 1
2123- SMS was delivered, no requests pending for subscr
2124DREF VLR subscr MSISDN:42342 usage increases to: 5
2125 llist_count(&vsub->cs.requests) == 0
2126DREF VLR subscr MSISDN:42342 usage decreases to: 4
2127- conn is still open to wait for SMS ack dance
2128 llist_count(&net->subscr_conns) == 1
2129- MS replies with CP-ACK for received SMS
2130 MSC <--RAN_GERAN_A-- MS: SMS:0x04
2131DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
2132DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
2133DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
2134DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002135DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
2136DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002137DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
2138 llist_count(&net->subscr_conns) == 1
2139- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
2140 MSC <--RAN_GERAN_A-- MS: SMS:0x01
2141DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
2142DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2143DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
2144DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
2145- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
2146- DTAP matches expected message
2147DREF VLR subscr MSISDN:42342 usage decreases to: 3
2148DREF VLR subscr MSISDN:42342 usage decreases to: 2
2149DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002150DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
2151DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002152DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
2153DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2154DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2155DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
2156DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
2157DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
2158DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
2159- BSSAP Clear --RAN_GERAN_A--> MS
2160DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
2161DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
2162DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
2163DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
2164DRLL subscr MSISDN:42342: Freeing subscriber connection
2165DREF VLR subscr MSISDN:42342 usage decreases to: 1
2166 dtap_tx_confirmed == 1
2167 bssap_clear_sent == 1
2168- SMS is done, conn is gone
2169 llist_count(&net->subscr_conns) == 0
2170---
2171- subscriber detaches
2172 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
2173 new conn
2174DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2175DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
2176DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
2177DREF VLR subscr MSISDN:42342 usage increases to: 2
2178DMM IMSI DETACH for MSISDN:42342
2179DREF VLR subscr MSISDN:42342 usage decreases to: 1
2180DREF VLR subscr MSISDN:42342 usage decreases to: 0
2181DREF freeing VLR subscr MSISDN:42342
2182DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
2183- BSSAP Clear --RAN_GERAN_A--> MS
2184DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
2185DRLL Freeing subscriber connection with NULL subscriber
2186 bssap_clear_sent == 1
2187 llist_count(&net->subscr_conns) == 0
2188===== test_gsm_ciph_in_umts_env: SUCCESS
2189
2190full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002191talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002192
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002193===== test_a5_3_not_supported
2194- Location Update request causes a GSUP Send Auth Info request to HLR
2195 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
2196 new conn
2197DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2198DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
2199DREF unknown: MSC conn use + fsm == 2 (0x5)
2200DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
2201DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
2202DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
2203DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
2204DMM LU/new-LAC: 1/23
2205DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
2206DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
2207DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
2208DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
2209DREF VLR subscr unknown usage increases to: 1
2210DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
2211DVLR New subscr, IMSI: 901700000004620
2212DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2213DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2214DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
2215DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
2216DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
2217DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
2218DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
2219DVLR GSUP tx: 08010809710000004026f0
2220GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
2221DVLR 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 +01002222DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002223DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
2224 lu_result_sent == 0
2225- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
2226<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2227DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2228DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2229DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
2230DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
2231DVLR 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 +01002232DVLR 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 Hofmeyra7fd88c2018-03-02 01:50:42 +01002233- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
2234- ...rand=585df1ae287f6e273dce07090d61320b
2235- ...expecting sres=2d8b2c3e
2236DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2237<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
2238 lu_result_sent == 0
2239 auth_request_sent == 1
2240---
2241- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- alas, no matching cipher can be found, abort and release
2242 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
2243DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
2244DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
2245DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
2246DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
2247DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
2248DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
2249DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
2250DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
2251DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2252DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
2253DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
2254DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
2255DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
2256DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
2257DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
2258DMM -> CIPHER MODE COMMAND IMSI:901700000004620
2259DMSC CLASSMARK 2 unknown, assuming MS doesn't support A5/3
2260DMM IMSI:901700000004620: cannot start ciphering, no intersection between MSC-configured and MS-supported A5 algorithms
2261- ERROR sending ciphering mode command: rc=-95
2262DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Failed to send Ciphering Mode Command
2263- sending LU Reject for IMSI:901700000004620, cause 17
2264DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
2265DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
2266DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
2267DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
2268DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
2269DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2270DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2271DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
2272DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
2273DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
2274DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
2275DMM msc_subscr_conn_close(vsub=IMSI:901700000004620, cause=2): no conn fsm, releasing directly without release event.
2276- BSSAP Clear --RAN_GERAN_A--> MS
2277DREF IMSI:901700000004620: MSC conn use - fsm == 1 (0x2)
2278DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
2279DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
2280DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
2281DRLL subscr IMSI:901700000004620: Freeing subscriber connection
2282DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
2283DREF freeing VLR subscr IMSI:901700000004620
2284 lu_result_sent == 2
2285 llist_count(&net->subscr_conns) == 0
2286===== test_a5_3_not_supported: SUCCESS
2287
2288full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002289talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002290
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002291full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002292talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002293