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