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