blob: 632f13ea022641af09ee0bd4bcc7de9e1942d838 [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2talloc_total_blocks(tall_bsc_ctx) == 12
3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01004===== test_ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01005- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01006 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01007 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01008DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01009DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010010DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +020011DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
12DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
13DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +020014DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010015DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +010016DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010017DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
18DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
19DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
20DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
21DREF VLR subscr unknown usage increases to: 1
22DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
23DVLR New subscr, IMSI: 901700000004620
24DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +020025DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010026DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
27DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
28DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
29DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
30DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
31DVLR GSUP tx: 08010809710000004026f0
32GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
33DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010034DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010035DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010036 lu_result_sent == 0
37- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
38<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
39DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
40DREF VLR subscr IMSI:901700000004620 usage increases to: 2
41DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
42DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
43DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +010044DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010045- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
46- ...rand=585df1ae287f6e273dce07090d61320b
47- ...expecting sres=2d8b2c3e
48DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
49<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
50 lu_result_sent == 0
51 auth_request_sent == 1
52- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +010053 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +010054DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010055DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010056DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
57DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +010058DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010059DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
60DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
61DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
62DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
63DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
64DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
65DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
66DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
67DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +010068DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +010069DMM -> CIPHER MODE COMMAND IMSI:901700000004620
70- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
71- ...perm algo: 2
72- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010073DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010074DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010075DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010076 lu_result_sent == 0
77- needs ciph, not yet accepted
78msc_subscr_conn_is_accepted() == false
79 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +010080DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
81DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
82DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
83DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
84DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
85DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +010086DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
87DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010088 lu_result_sent == 0
89- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +010090 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010091DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
92DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
93DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
94DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
95DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
96DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
97DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
98DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
99DVLR GSUP tx: 04010809710000004026f0
100GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
101DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
102 lu_result_sent == 0
103- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
104<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
105DVLR GSUP rx 17: 10010809710000004026f00804036470f1
106DREF VLR subscr IMSI:901700000004620 usage increases to: 2
107DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100108DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100109DVLR GSUP tx: 12010809710000004026f0
110GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
111DREF VLR subscr MSISDN:46071 usage decreases to: 1
112<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
113 lu_result_sent == 0
114- HLR also sends GSUP _UPDATE_LOCATION_RESULT
115<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
116DVLR GSUP rx 11: 06010809710000004026f0
117DREF VLR subscr MSISDN:46071 usage increases to: 2
118DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
119DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
120DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
121DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
122DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
123DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
124DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
125DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
126DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
127DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
128DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
129DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
130DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
131DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
132DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
133DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
134DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
135DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
136DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
137DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
138DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
139DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
140- sending LU Accept for MSISDN:46071
141DREF VLR subscr MSISDN:46071 usage increases to: 3
142DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
143DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
144DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
145DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
146DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
147DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
148DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200149DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200150DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100151DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
152DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200153DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
154DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100155DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
156DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
157DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
158DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
159DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
160DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200161- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100162DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100163DRLL subscr MSISDN:46071: Freeing subscriber connection
164DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200165DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
166DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100167DREF VLR subscr MSISDN:46071 usage decreases to: 1
168<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +0200169 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100170- LU was successful, and the conn has already been closed
171 lu_result_sent == 1
172 llist_count(&net->subscr_conns) == 0
173---
174- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100175 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100176 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100177DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100178DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100179DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100180DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200181DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
182DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
183DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200184DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100185DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
186DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
187DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
188DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
189DREF VLR subscr MSISDN:46071 usage increases to: 2
190DREF VLR subscr MSISDN:46071 usage increases to: 3
191DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
192DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
193DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
194DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
195DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
196DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100197DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100198- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
199- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
200- ...expecting sres=20bde240
201DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100202DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100203DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100204 auth_request_sent == 1
205 cm_service_result_sent == 0
206- needs auth, not yet accepted
207msc_subscr_conn_is_accepted() == false
208 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100209DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
210DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
211DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
212DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
213DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
214DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100215DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
216DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100217- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100218 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100219DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100220DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100221DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
222DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100223DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100224DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
225DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
226DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
227DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
228DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
229DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
230DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
231DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
232DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
233DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100234DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100235DMM -> CIPHER MODE COMMAND MSISDN:46071
236DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
237- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
238- ...perm algo: 2
239- ...key: 07fa7502e07e1c00
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100240DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100241DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100242DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100243 cm_service_result_sent == 0
244 cipher_mode_cmd_sent == 1
245- needs ciph, not yet accepted
246msc_subscr_conn_is_accepted() == false
247 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100248DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
249DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
250DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
251DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
252DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
253DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100254DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
255DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100256- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100257 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100258DRR MSISDN:46071: CIPHERING MODE COMPLETE
259DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
260DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
261DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
262DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
263DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
264DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
265DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
266DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
267DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200268DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200269DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
270DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100271DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
272DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100273 cm_service_result_sent == 0
274- a USSD request is serviced
275 expecting USSD:
276 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100277 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100278DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100279DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
280DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200281DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
282DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100283DMM USSD: Own number requested
284DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200285DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100286- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100287- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100288DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
289DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200290DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
291DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100292DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
293DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
294DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
295DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
296DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200297- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100298DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200299DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
300DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100301DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100302DRLL subscr MSISDN:46071: Freeing subscriber connection
303DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200304 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100305- all requests serviced, conn has been released
306 llist_count(&net->subscr_conns) == 0
307---
308- an SMS is sent, MS is paged
309DREF VLR subscr MSISDN:46071 usage increases to: 2
310 llist_count(&vsub->cs.requests) == 0
311DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200312DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100313 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200314 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100315DREF VLR subscr MSISDN:46071 usage increases to: 4
316 llist_count(&vsub->cs.requests) == 1
317DREF VLR subscr MSISDN:46071 usage decreases to: 3
318 paging_sent == 1
319 paging_stopped == 0
320- the subscriber and its pending request should remain
321DREF VLR subscr MSISDN:46071 usage increases to: 4
322 llist_count(&vsub->cs.requests) == 1
323DREF VLR subscr MSISDN:46071 usage decreases to: 3
324- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100325 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100326 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100327DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100328DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100329DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100330DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200331DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
332DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
333DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200334DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100335DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
336DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
337DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
338DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
339DREF VLR subscr MSISDN:46071 usage increases to: 4
340DREF VLR subscr MSISDN:46071 usage increases to: 5
341DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
342DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
343DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
344DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
345DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
346DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100347DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100348- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
349- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
350- ...expecting sres=a29514ae
351DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100352DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100353DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100354 auth_request_sent == 1
355- needs auth, not yet accepted
356msc_subscr_conn_is_accepted() == false
357 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100358DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
359DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
360DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
361DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
362DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
363DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100364DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
365DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100366- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100367 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100368DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100369DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100370DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
371DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100372DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100373DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
374DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
375DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
376DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
377DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
378DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
379DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
380DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
381DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
382DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100383DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100384DMM -> CIPHER MODE COMMAND MSISDN:46071
385DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
386- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
387- ...perm algo: 2
388- ...key: e2b234f807886400
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100389DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100390DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100391DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100392 cipher_mode_cmd_sent == 1
393- needs ciph, not yet accepted
394msc_subscr_conn_is_accepted() == false
395 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100396DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
397DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
398DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
399DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
400DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
401DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100402DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
403DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100404- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100405 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100406DRR MSISDN:46071: CIPHERING MODE COMPLETE
407DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
408DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
409DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
410DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
411DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
412DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
413DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
414DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
415DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200416DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200417DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
418DPAG Paging success for MSISDN:46071 (event=0)
419DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100420DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100421DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100422DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x14)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200423DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100424- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100425- DTAP matches expected message
426DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100427DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
428DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100429 dtap_tx_confirmed == 1
430 paging_stopped == 1
431- SMS was delivered, no requests pending for subscr
432DREF VLR subscr MSISDN:46071 usage increases to: 5
433 llist_count(&vsub->cs.requests) == 0
434DREF VLR subscr MSISDN:46071 usage decreases to: 4
435- conn is still open to wait for SMS ack dance
436 llist_count(&net->subscr_conns) == 1
437- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100438 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100439DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100440DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200441DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
442DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100443DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
444DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100445DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100446 llist_count(&net->subscr_conns) == 1
447- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100448 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100449DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100450DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200451DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
452DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100453- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100454- DTAP matches expected message
455DREF VLR subscr MSISDN:46071 usage decreases to: 3
456DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100457DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100458DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
459DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200460DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
461DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100462DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
463DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
464DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
465DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
466DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200467- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100468DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200469DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
470DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100471DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100472DRLL subscr MSISDN:46071: Freeing subscriber connection
473DREF VLR subscr MSISDN:46071 usage decreases to: 1
474 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200475 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100476- SMS is done, conn is gone
477 llist_count(&net->subscr_conns) == 0
478---
479- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100480 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100481 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100482DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100483DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100484DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
485DREF VLR subscr MSISDN:46071 usage increases to: 2
486DMM IMSI DETACH for MSISDN:46071
487DREF VLR subscr MSISDN:46071 usage decreases to: 1
488DREF VLR subscr MSISDN:46071 usage decreases to: 0
489DREF freeing VLR subscr MSISDN:46071
490DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200491- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100492DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100493DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200494 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100495 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100496===== test_ciph: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100497
498full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200499talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100500
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100501===== test_ciph_tmsi
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100502- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100503 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100504 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100505DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100506DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100507DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200508DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
509DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
510DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200511DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100512DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100513DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100514DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
515DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
516DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
517DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
518DREF VLR subscr unknown usage increases to: 1
519DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
520DVLR New subscr, IMSI: 901700000004620
521DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200522DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100523DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
524DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
525DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
526DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
527DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
528DVLR GSUP tx: 08010809710000004026f0
529GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
530DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100531DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100532DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100533 lu_result_sent == 0
534- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
535<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
536DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
537DREF VLR subscr IMSI:901700000004620 usage increases to: 2
538DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
539DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
540DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100541DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100542- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
543- ...rand=585df1ae287f6e273dce07090d61320b
544- ...expecting sres=2d8b2c3e
545DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
546<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
547 auth_request_sent == 1
548 lu_result_sent == 0
549- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100550 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100551DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100552DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100553DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
554DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100555DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100556DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
557DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
558DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
559DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
560DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
561DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
562DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
563DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
564DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +0100565DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100566DMM -> CIPHER MODE COMMAND IMSI:901700000004620
567- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
568- ...perm algo: 2
569- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100570DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100571DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100572DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100573 lu_result_sent == 0
574 auth_request_sent == 1
575- needs ciph, not yet accepted
576msc_subscr_conn_is_accepted() == false
577 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100578DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
579DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
580DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
581DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
582DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
583DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100584DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
585DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100586 lu_result_sent == 0
587- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100588 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100589DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
590DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
591DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
592DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
593DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
594DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
595DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
596DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
597DVLR GSUP tx: 04010809710000004026f0
598GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
599DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
600 lu_result_sent == 0
601- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
602<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
603DVLR GSUP rx 17: 10010809710000004026f00804036470f1
604DREF VLR subscr IMSI:901700000004620 usage increases to: 2
605DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100606DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100607DVLR GSUP tx: 12010809710000004026f0
608GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
609DREF VLR subscr MSISDN:46071 usage decreases to: 1
610<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
611 lu_result_sent == 0
612- HLR also sends GSUP _UPDATE_LOCATION_RESULT
613<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
614DVLR GSUP rx 11: 06010809710000004026f0
615DREF VLR subscr MSISDN:46071 usage increases to: 2
616DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
617DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
618DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
619DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
620DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
621DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
622DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
623DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
624DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
625DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
626DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
627DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
628DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
629DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
630DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
631DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
632DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
633DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
634DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
635DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
636DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
637DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
638DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
639DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
640- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
641DREF VLR subscr MSISDN:46071 usage decreases to: 1
642<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
643- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
644 llist_count(&net->subscr_conns) == 1
645 lu_result_sent == 1
646msc_subscr_conn_is_accepted() == false
647 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100648DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
649DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
650DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
651DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
652DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
653DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100654DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
655DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100656- even though the TMSI is not acked, we can already find the subscr with it
657DREF VLR subscr MSISDN:46071 usage increases to: 2
658 vsub != NULL == 1
659 strcmp(vsub->imsi, imsi) == 0
660 vsub->tmsi_new == 0x03020100
661 vsub->tmsi == 0xffffffff
662DREF VLR subscr MSISDN:46071 usage decreases to: 1
663- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100664 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100665DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100666DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100667DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
668DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
669DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
670DREF VLR subscr MSISDN:46071 usage increases to: 2
671DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
672DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
673DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
674DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
675DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
676DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
677DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200678DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200679DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100680DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
681DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200682DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
683DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100684DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
685DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
686DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
687DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
688DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
689DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200690- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100691DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200692DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
693DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100694DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100695DRLL subscr MSISDN:46071: Freeing subscriber connection
696DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200697 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100698- LU was successful, and the conn has already been closed
699 llist_count(&net->subscr_conns) == 0
700- Subscriber has the new TMSI
701DREF VLR subscr MSISDN:46071 usage increases to: 2
702 vsub != NULL == 1
703 strcmp(vsub->imsi, imsi) == 0
704 vsub->tmsi_new == 0xffffffff
705 vsub->tmsi == 0x03020100
706DREF VLR subscr MSISDN:46071 usage decreases to: 1
707---
708- after a while, a new conn sends a CM Service Request using above TMSI. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100709 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100710 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100711DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100712DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100713DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100714DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200715DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
716DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
717DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200718DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100719DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
720DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
721DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
722DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
723DREF VLR subscr MSISDN:46071 usage increases to: 2
724DREF VLR subscr MSISDN:46071 usage increases to: 3
725DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
726DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
727DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
728DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
729DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
730DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100731DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100732- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
733- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
734- ...expecting sres=20bde240
735DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100736DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100737DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100738 auth_request_sent == 1
739 cm_service_result_sent == 0
740- needs auth, not yet accepted
741msc_subscr_conn_is_accepted() == false
742 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100743DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
744DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
745DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
746DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
747DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
748DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100749DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
750DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100751- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100752 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100753DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100754DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100755DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
756DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100757DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100758DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
759DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
760DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
761DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
762DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
763DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
764DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
765DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
766DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
767DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100768DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100769DMM -> CIPHER MODE COMMAND MSISDN:46071
770DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
771- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
772- ...perm algo: 2
773- ...key: 07fa7502e07e1c00
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100774DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100775DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100776DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100777 cm_service_result_sent == 0
778 cipher_mode_cmd_sent == 1
779- needs ciph, not yet accepted
780msc_subscr_conn_is_accepted() == false
781 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100782DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
783DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
784DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
785DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
786DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
787DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100788DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
789DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100790- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100791 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100792DRR MSISDN:46071: CIPHERING MODE COMPLETE
793DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
794DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
795DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
796DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
797DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
798DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
799DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
800DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
801DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200802DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200803DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
804DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100805DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
806DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100807 cm_service_result_sent == 0
808- a USSD request is serviced
809 expecting USSD:
810 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100811 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100812DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100813DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
814DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200815DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
816DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100817DMM USSD: Own number requested
818DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200819DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100820- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100821- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100822DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
823DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200824DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
825DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100826DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
827DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
828DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
829DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
830DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200831- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100832DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200833DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
834DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100835DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100836DRLL subscr MSISDN:46071: Freeing subscriber connection
837DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200838 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100839- all requests serviced, conn has been released
840 llist_count(&net->subscr_conns) == 0
841---
842- an SMS is sent, MS is paged
843DREF VLR subscr MSISDN:46071 usage increases to: 2
844 llist_count(&vsub->cs.requests) == 0
845DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200846DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100847 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100848 paging_expecting_tmsi == 0x03020100
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100849DREF VLR subscr MSISDN:46071 usage increases to: 4
850 llist_count(&vsub->cs.requests) == 1
851DREF VLR subscr MSISDN:46071 usage decreases to: 3
852 paging_sent == 1
853 paging_stopped == 0
854- the subscriber and its pending request should remain
855DREF VLR subscr MSISDN:46071 usage increases to: 4
856 llist_count(&vsub->cs.requests) == 1
857DREF VLR subscr MSISDN:46071 usage decreases to: 3
858- MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100859 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100860 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100861DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100862DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100863DRR PAGING RESPONSE: MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100864DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200865DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
866DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
867DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200868DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100869DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
870DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
871DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
872DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
873DREF VLR subscr MSISDN:46071 usage increases to: 4
874DREF VLR subscr MSISDN:46071 usage increases to: 5
875DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
876DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
877DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
878DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
879DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
880DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100881DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100882- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
883- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
884- ...expecting sres=a29514ae
885DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100886DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100887DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100888 auth_request_sent == 1
889- needs auth, not yet accepted
890msc_subscr_conn_is_accepted() == false
891 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100892DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
893DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
894DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
895DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
896DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
897DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100898DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
899DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100900- MS sends Authen Response, VLR accepts and requests Ciphering
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100901 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100902DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100903DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100904DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
905DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100906DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100907DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
908DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
909DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
910DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
911DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
912DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
913DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
914DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
915DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
916DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100917DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100918DMM -> CIPHER MODE COMMAND MSISDN:46071
919DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
920- sending Ciphering Mode Command for MSISDN:46071: include_imeisv=0
921- ...perm algo: 2
922- ...key: e2b234f807886400
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100923DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100924DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100925DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100926 cipher_mode_cmd_sent == 1
927- needs ciph, not yet accepted
928msc_subscr_conn_is_accepted() == false
929 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100930DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
931DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
932DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
933DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
934DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
935DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100936DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
937DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100938- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100939 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100940DRR MSISDN:46071: CIPHERING MODE COMPLETE
941DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
942DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
943DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
944DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
945DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
946DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
947DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
948DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
949DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200950DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200951DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
952DPAG Paging success for MSISDN:46071 (event=0)
953DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100954DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100955DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100956DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x14)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200957DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100958- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100959- DTAP matches expected message
960DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100961DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
962DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100963 dtap_tx_confirmed == 1
964 paging_stopped == 1
965- SMS was delivered, no requests pending for subscr
966DREF VLR subscr MSISDN:46071 usage increases to: 5
967 llist_count(&vsub->cs.requests) == 0
968DREF VLR subscr MSISDN:46071 usage decreases to: 4
969- conn is still open to wait for SMS ack dance
970 llist_count(&net->subscr_conns) == 1
971- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100972 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100973DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100974DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200975DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
976DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100977DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
978DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100979DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100980 llist_count(&net->subscr_conns) == 1
981- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100982 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100983DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100984DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200985DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
986DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100987- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100988- DTAP matches expected message
989DREF VLR subscr MSISDN:46071 usage decreases to: 3
990DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100991DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100992DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
993DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200994DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
995DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100996DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
997DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
998DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
999DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
1000DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001001- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001002DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001003DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
1004DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001005DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001006DRLL subscr MSISDN:46071: Freeing subscriber connection
1007DREF VLR subscr MSISDN:46071 usage decreases to: 1
1008 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001009 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001010- SMS is done, conn is gone
1011 llist_count(&net->subscr_conns) == 0
1012---
1013- subscriber detaches, using TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001014 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001015 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001016DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001017DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001018DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1019DREF VLR subscr MSISDN:46071 usage increases to: 2
1020DMM IMSI DETACH for MSISDN:46071
1021DREF VLR subscr MSISDN:46071 usage decreases to: 1
1022DREF VLR subscr MSISDN:46071 usage decreases to: 0
1023DREF freeing VLR subscr MSISDN:46071
1024DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001025- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001026DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001027DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001028 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001029 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001030===== test_ciph_tmsi: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001031
1032full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001033talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001034
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001035===== test_ciph_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001036- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001037 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001038 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001039DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001040DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001041DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001042DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1043DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1044DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001045DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001046DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001047DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001048DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1049DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1050DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
1051DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1052DREF VLR subscr unknown usage increases to: 1
1053DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1054DVLR New subscr, IMSI: 901700000004620
1055DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001056DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001057DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1058DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1059DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1060DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1061DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1062DVLR GSUP tx: 08010809710000004026f0
1063GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1064DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001065DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001066DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001067 lu_result_sent == 0
1068- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1069<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1070DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1071DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1072DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1073DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1074DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001075DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001076- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1077- ...rand=585df1ae287f6e273dce07090d61320b
1078- ...expecting sres=2d8b2c3e
1079DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1080<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1081 auth_request_sent == 1
1082 lu_result_sent == 0
1083- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001084 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001085DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001086DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001087DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1088DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001089DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001090DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1091DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1092DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1093DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1094DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1095DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1096DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1097DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1098DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001099DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001100DMM -> CIPHER MODE COMMAND IMSI:901700000004620
1101- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
1102- ...perm algo: 2
1103- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001104DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001105DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001106DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001107 lu_result_sent == 0
1108- needs ciph, not yet accepted
1109msc_subscr_conn_is_accepted() == false
1110 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001111DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1112DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1113DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1114DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1115DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1116DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001117DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1118DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001119 lu_result_sent == 0
1120- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001121 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001122DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
1123DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1124DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1125DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1126DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1127DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1128DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1129DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1130DVLR GSUP tx: 04010809710000004026f0
1131GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1132DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1133 lu_result_sent == 0
1134- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1135<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1136DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1137DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1138DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001139DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001140DVLR GSUP tx: 12010809710000004026f0
1141GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1142DREF VLR subscr MSISDN:46071 usage decreases to: 1
1143<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1144 lu_result_sent == 0
1145- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1146<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1147DVLR GSUP rx 11: 06010809710000004026f0
1148DREF VLR subscr MSISDN:46071 usage increases to: 2
1149DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1150DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1151DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1152DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1153DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1154DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1155DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1156DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1157DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1158DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1159DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1160DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1161DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1162DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1163DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1164DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1165DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1166DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1167DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1168DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1169DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1170DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1171DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001172DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001173- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001174- DTAP matches expected message
1175DREF VLR subscr MSISDN:46071 usage decreases to: 1
1176<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1177- We will only do business when the IMEI is known
1178 llist_count(&net->subscr_conns) == 1
1179DREF VLR subscr MSISDN:46071 usage increases to: 2
1180 vsub->imei[0] == 0
1181DREF VLR subscr MSISDN:46071 usage decreases to: 1
1182msc_subscr_conn_is_accepted() == false
1183 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001184DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1185DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1186DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1187DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1188DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1189DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001190DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1191DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001192- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001193 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001194DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001195DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001196DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1197DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001198DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1199DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1200- sending LU Accept for MSISDN:46071
1201DREF VLR subscr MSISDN:46071 usage increases to: 2
1202DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
1203DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1204DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1205DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1206DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1207DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1208DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001209DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001210DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001211DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1212DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001213DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1214DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001215DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1216DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1217DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1218DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1219DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1220DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001221- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001222DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001223DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1224DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001225DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001226DRLL subscr MSISDN:46071: Freeing subscriber connection
1227DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001228 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001229- LU was successful, and the conn has already been closed
1230 lu_result_sent == 1
1231 llist_count(&net->subscr_conns) == 0
1232- Subscriber has the IMEI
1233DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001234 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001235DREF VLR subscr MSISDN:46071 usage decreases to: 1
1236---
1237- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001238 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001239 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001240DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001241DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001242DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1243DREF VLR subscr MSISDN:46071 usage increases to: 2
1244DMM IMSI DETACH for MSISDN:46071
1245DREF VLR subscr MSISDN:46071 usage decreases to: 1
1246DREF VLR subscr MSISDN:46071 usage decreases to: 0
1247DREF freeing VLR subscr MSISDN:46071
1248DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001249- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001250DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001251DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001252 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001253 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001254===== test_ciph_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001255
1256full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001257talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001258
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001259===== test_ciph_imeisv
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001260- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001261 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001262 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001263DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001264DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001265DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001266DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1267DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1268DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001269DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001270DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001271DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001272DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1273DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1274DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
1275DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1276DREF VLR subscr unknown usage increases to: 1
1277DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1278DVLR New subscr, IMSI: 901700000004620
1279DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001280DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001281DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1282DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1283DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1284DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1285DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1286DVLR GSUP tx: 08010809710000004026f0
1287GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1288DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001289DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001290DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001291 lu_result_sent == 0
1292- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1293<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1294DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1295DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1296DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1297DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1298DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001299DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001300- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1301- ...rand=585df1ae287f6e273dce07090d61320b
1302- ...expecting sres=2d8b2c3e
1303DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1304<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1305 auth_request_sent == 1
1306 lu_result_sent == 0
1307- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001308 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001309DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001310DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001311DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1312DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001313DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001314DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1315DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1316DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1317DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1318DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1319DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1320DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1321DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1322DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001323DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001324DMM -> CIPHER MODE COMMAND IMSI:901700000004620
1325- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=1
1326- ...perm algo: 2
1327- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001328DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001329DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001330DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001331 cipher_mode_cmd_sent == 1
1332 cipher_mode_cmd_sent_with_imeisv == 1
1333 lu_result_sent == 0
1334- needs ciph, not yet accepted
1335msc_subscr_conn_is_accepted() == false
1336 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001337DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1338DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1339DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1340DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1341DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1342DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001343DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1344DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001345 lu_result_sent == 0
1346DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1347 vsub->imeisv[0] == 0
1348DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1349- MS sends Ciphering Mode Complete with IMEISV, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001350 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001351DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
1352DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001353DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: got IMEISV: 4234234234234275F
1354DVLR set IMEISV on subscriber; IMSI=901700000004620 IMEISV=4234234234234275
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001355DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1356DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1357DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1358DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1359DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1360DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1361DVLR GSUP tx: 04010809710000004026f0
1362GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1363DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1364 lu_result_sent == 0
1365- Subscriber has the IMEISV
1366DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001367 strcmp(vsub->imeisv, "4234234234234275") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001368DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1369msc_subscr_conn_is_accepted() == false
1370 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001371DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1372DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1373DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1374DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1375DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1376DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001377DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1378DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001379- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1380<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1381DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1382DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1383DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001384DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001385DVLR GSUP tx: 12010809710000004026f0
1386GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1387DREF VLR subscr MSISDN:46071 usage decreases to: 1
1388<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1389 lu_result_sent == 0
1390- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1391<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1392DVLR GSUP rx 11: 06010809710000004026f0
1393DREF VLR subscr MSISDN:46071 usage increases to: 2
1394DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1395DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1396DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1397DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1398DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1399DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1400DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1401DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1402DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1403DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1404DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1405DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1406DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1407DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1408DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1409DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1410DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1411DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1412DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1413DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1414DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1415DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1416- sending LU Accept for MSISDN:46071
1417DREF VLR subscr MSISDN:46071 usage increases to: 3
1418DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1419DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1420DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1421DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1422DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1423DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1424DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001425DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001426DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001427DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1428DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001429DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1430DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001431DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1432DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1433DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1434DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1435DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1436DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001437- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001438DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001439DRLL subscr MSISDN:46071: Freeing subscriber connection
1440DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001441DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1442DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001443DREF VLR subscr MSISDN:46071 usage decreases to: 1
1444<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +02001445 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001446- LU was successful, and the conn has already been closed
1447 lu_result_sent == 1
1448 llist_count(&net->subscr_conns) == 0
1449---
1450- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001451 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001452 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001453DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001454DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001455DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1456DREF VLR subscr MSISDN:46071 usage increases to: 2
1457DMM IMSI DETACH for MSISDN:46071
1458DREF VLR subscr MSISDN:46071 usage decreases to: 1
1459DREF VLR subscr MSISDN:46071 usage decreases to: 0
1460DREF freeing VLR subscr MSISDN:46071
1461DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001462- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001463DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001464DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001465 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001466 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001467===== test_ciph_imeisv: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001468
1469full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001470talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001471
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001472===== test_ciph_tmsi_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001473- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001474 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001475 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001476DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001477DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001478DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001479DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1480DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1481DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001482DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001483DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001484DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001485DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1486DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1487DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
1488DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1489DREF VLR subscr unknown usage increases to: 1
1490DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1491DVLR New subscr, IMSI: 901700000004620
1492DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001493DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001494DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1495DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1496DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1497DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1498DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1499DVLR GSUP tx: 08010809710000004026f0
1500GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1501DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001502DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001503DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001504 lu_result_sent == 0
1505- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1506<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1507DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1508DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1509DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1510DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1511DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001512DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001513- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1514- ...rand=585df1ae287f6e273dce07090d61320b
1515- ...expecting sres=2d8b2c3e
1516DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1517<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1518 auth_request_sent == 1
1519 lu_result_sent == 0
1520- MS sends Authen Response, VLR accepts and sends Ciphering Mode Command to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001521 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001522DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001523DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001524DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1525DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001526DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001527DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1528DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1529DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1530DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1531DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1532DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1533DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1534DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1535DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001536DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001537DMM -> CIPHER MODE COMMAND IMSI:901700000004620
1538- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
1539- ...perm algo: 2
1540- ...key: 61855fb81fc2a800
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001541DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001542DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001543DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001544 lu_result_sent == 0
1545- needs ciph, not yet accepted
1546msc_subscr_conn_is_accepted() == false
1547 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001548DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1549DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1550DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1551DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1552DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1553DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001554DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1555DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001556 lu_result_sent == 0
1557- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001558 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001559DRR IMSI:901700000004620: CIPHERING MODE COMPLETE
1560DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1561DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1562DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1563DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1564DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1565DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1566DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1567DVLR GSUP tx: 04010809710000004026f0
1568GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1569DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1570 lu_result_sent == 0
1571- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1572<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1573DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1574DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1575DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001576DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001577DVLR GSUP tx: 12010809710000004026f0
1578GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1579DREF VLR subscr MSISDN:46071 usage decreases to: 1
1580<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1581 lu_result_sent == 0
1582- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1583<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1584DVLR GSUP rx 11: 06010809710000004026f0
1585DREF VLR subscr MSISDN:46071 usage increases to: 2
1586DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1587DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1588DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1589DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1590DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1591DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1592DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1593DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1594DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1595DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1596DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1597DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1598DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1599DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1600DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1601DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1602DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1603DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1604DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1605DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1606DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1607DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1608DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI_TMSI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001609DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001610- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001611- DTAP matches expected message
1612DREF VLR subscr MSISDN:46071 usage decreases to: 1
1613<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1614- We will only do business when the IMEI is known
1615 llist_count(&net->subscr_conns) == 1
1616DREF VLR subscr MSISDN:46071 usage increases to: 2
1617 vsub->imei[0] == 0
1618DREF VLR subscr MSISDN:46071 usage decreases to: 1
1619msc_subscr_conn_is_accepted() == false
1620 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001621DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1622DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1623DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1624DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1625DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1626DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001627DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1628DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001629- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001630 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001631DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001632DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001633DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1634DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001635DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1636DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1637DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
1638DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1639- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001640DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001641DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001642- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1643 llist_count(&net->subscr_conns) == 1
1644 lu_result_sent == 1
1645msc_subscr_conn_is_accepted() == false
1646 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001647DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1648DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1649DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1650DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1651DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1652DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001653DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1654DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001655- even though the TMSI is not acked, we can already find the subscr with it
1656DREF VLR subscr MSISDN:46071 usage increases to: 2
1657 vsub != NULL == 1
1658 strcmp(vsub->imsi, imsi) == 0
1659 vsub->tmsi_new == 0x03020100
1660 vsub->tmsi == 0xffffffff
1661DREF VLR subscr MSISDN:46071 usage decreases to: 1
1662- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001663 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001664DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001665DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001666DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1667DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1668DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1669DREF VLR subscr MSISDN:46071 usage increases to: 2
1670DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1671DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1672DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1673DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1674DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1675DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1676DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001677DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001678DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001679DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1680DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001681DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1682DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001683DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1684DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1685DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1686DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1687DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1688DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001689- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001690DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001691DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1692DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001693DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001694DRLL subscr MSISDN:46071: Freeing subscriber connection
1695DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001696 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001697- LU was successful, and the conn has already been closed
1698 llist_count(&net->subscr_conns) == 0
1699- Subscriber has the IMEI and TMSI
1700DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001701 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001702 vsub->tmsi == 0x03020100
1703DREF VLR subscr MSISDN:46071 usage decreases to: 1
1704---
1705- subscriber detaches, using TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001706 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001707 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001708DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001709DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001710DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1711DREF VLR subscr MSISDN:46071 usage increases to: 2
1712DMM IMSI DETACH for MSISDN:46071
1713DREF VLR subscr MSISDN:46071 usage decreases to: 1
1714DREF VLR subscr MSISDN:46071 usage decreases to: 0
1715DREF freeing VLR subscr MSISDN:46071
1716DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001717- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001718DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001719DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001720 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001721 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001722===== test_ciph_tmsi_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001723
1724full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001725talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001726
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001727===== test_gsm_ciph_in_umts_env
1728- Location Update request causes a GSUP Send Auth Info request to HLR
1729 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1730 new conn
1731DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1732DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1733DREF unknown: MSC conn use + fsm == 2 (0x5)
1734DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1735DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1736DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001737DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001738DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1739DMM LU/new-LAC: 0/23
1740DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1741DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1742DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth+Ciph
1743DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1744DREF VLR subscr unknown usage increases to: 1
1745DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1746DVLR New subscr, IMSI: 901700000010650
1747DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1748DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1749DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1750DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1751DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1752DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1753DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1754DVLR GSUP tx: 08010809710000000156f0
1755GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1756DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001757DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001758DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1759 lu_result_sent == 0
1760- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends *UMTS AKA* Auth Req to MS
1761<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220104ac8d1cd1a51937597ca1016fe69a0fa2104dacc4b2622087a75f0ac9b84440023103747da4e31545baa2db59e500bdae04724108544d35b945ccba01a7f1293575291c325102d837d2b0d6f00004b282d5acf23428d270837527064741f8ddb03622010b2661531b97b12c5a2edc21a0ed16fc521042fb4cfad2208da149b11d473f40023103fe013b1a428ea737c37f8f0288c8edf2410f275438c02b97e4d6f639dddda3d10b9251078cdd96c60840000322f421b3bb778b12708ed3ebf9cb6ea48ed0362201054d8f19778056666b41c8c25e52eb60c21040ff61e0f220826ec67fad307300023102868b0922c652616f1c975e3eaf7943a24106a84a20b1bc13ec9840466406d2dd91e251053f3e5632b3d00008865dd54d49663f2270886e848a9e7ad8cd5036220101f05607ff9c8984f46ad97f8c9a94982210491a36e3d22085d84421884fdcc0023102171fef54b81e30c83a598a5e44f634c2410f02d088697509827565b46938fece21125101b43bbf9815e00001cb9b2a9f6b8a77c2708373e67d62e719c510362201080d89a58a2a41050918caf68a4e93c642104a319f5f12208883df2b8672930002310fa5d70f929ff298efb160413698dc1072410ae9a3d8ce70ce13bac297bdb91cd6c6825105c0dc2eeaefa0000396882a1fe2cf80b270865ab1cad216bfe87
1762DVLR GSUP rx 511: 0a010809710000000156f0036220104ac8d1cd1a51937597ca1016fe69a0fa2104dacc4b2622087a75f0ac9b84440023103747da4e31545baa2db59e500bdae04724108544d35b945ccba01a7f1293575291c325102d837d2b0d6f00004b282d5acf23428d270837527064741f8ddb03622010b2661531b97b12c5a2edc21a0ed16fc521042fb4cfad2208da149b11d473f40023103fe013b1a428ea737c37f8f0288c8edf2410f275438c02b97e4d6f639dddda3d10b9251078cdd96c60840000322f421b3bb778b12708ed3ebf9cb6ea48ed0362201054d8f19778056666b41c8c25e52eb60c21040ff61e0f220826ec67fad307300023102868b0922c652616f1c975e3eaf7943a24106a84a20b1bc13ec9840466406d2dd91e251053f3e5632b3d00008865dd54d49663f2270886e848a9e7ad8cd5036220101f05607ff9c8984f46ad97f8c9a94982210491a36e3d22085d84421884fdcc0023102171fef54b81e30c83a598a5e44f634c2410f02d088697509827565b46938fece21125101b43bbf9815e00001cb9b2a9f6b8a77c2708373e67d62e719c510362201080d89a58a2a41050918caf68a4e93c642104a319f5f12208883df2b8672930002310fa5d70f929ff298efb160413698dc1072410ae9a3d8ce70ce13bac297bdb91cd6c6825105c0dc2eeaefa0000396882a1fe2cf80b270865ab1cad216bfe87
1763DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1764DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1765DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1766DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001767DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001768- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1769- ...rand=4ac8d1cd1a51937597ca1016fe69a0fa
1770- ...autn=2d837d2b0d6f00004b282d5acf23428d
1771- ...expecting res=37527064741f8ddb
1772DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1773<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1774 auth_request_sent == 1
1775 lu_result_sent == 0
1776- MS sends *GSM AKA* Authen Response, VLR accepts and sends Ciphering Mode Command to MS
1777 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1778DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1779DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1780DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = dacc4b26)
1781DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001782DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: dacc4b26 (4 bytes)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001783DVLR SUBSCR(IMSI:901700000010650) AUTH established GSM security context
1784DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1785DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1786DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1787DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1788DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1789DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1790DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1791DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1792DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
1793DMM -> CIPHER MODE COMMAND IMSI:901700000010650
1794- sending Ciphering Mode Command for IMSI:901700000010650: include_imeisv=0
1795- ...perm algo: 2
Neels Hofmeyr7795a192018-03-10 00:26:36 +01001796- ...key: 7a75f0ac9b844400
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001797DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001798DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001799DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
1800 lu_result_sent == 0
1801- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
1802 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
1803DRR IMSI:901700000010650: CIPHERING MODE COMPLETE
1804DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1805DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1806DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1807DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1808DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1809DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1810DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1811DVLR GSUP tx: 04010809710000000156f0
1812GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1813DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1814 lu_result_sent == 0
1815- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1816<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1817DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1818DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1819DVLR IMSI:901700000010650 has MSISDN:42342
1820DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1821DVLR GSUP tx: 12010809710000000156f0
1822GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1823DREF VLR subscr MSISDN:42342 usage decreases to: 1
1824<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1825 lu_result_sent == 0
1826- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1827<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1828DVLR GSUP rx 11: 06010809710000000156f0
1829DREF VLR subscr MSISDN:42342 usage increases to: 2
1830DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1831DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1832DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1833DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1834DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1835DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1836DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1837DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1838DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1839DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1840DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1841DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1842DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1843DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1844DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1845DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1846DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1847DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1848DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1849DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1850DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1851DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1852- sending LU Accept for MSISDN:42342
1853DREF VLR subscr MSISDN:42342 usage increases to: 3
1854DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1855DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1856DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1857DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1858DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1859DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1860DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1861DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001862DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001863DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1864DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001865DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1866DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1867DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1868DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1869DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1870DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1871DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1872DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1873- BSSAP Clear --RAN_GERAN_A--> MS
1874DREF MSISDN:42342: MSC conn use - fsm == 0 (0x0)
1875DRLL subscr MSISDN:42342: Freeing subscriber connection
1876DREF VLR subscr MSISDN:42342 usage decreases to: 2
1877DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1878DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1879DREF VLR subscr MSISDN:42342 usage decreases to: 1
1880<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1881 bssap_clear_sent == 1
1882- LU was successful, and the conn has already been closed
1883 lu_result_sent == 1
1884 llist_count(&net->subscr_conns) == 0
1885---
1886- after a while, a new conn sends a CM Service Request. VLR responds with *UMTS AKA* Auth Req, 2nd auth vector
1887 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
1888 new conn
1889DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1890DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
1891DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
1892DREF unknown: MSC conn use + fsm == 2 (0x5)
1893DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1894DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1895DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02001896DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001897DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1898DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1899DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
1900DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1901DREF VLR subscr MSISDN:42342 usage increases to: 2
1902DREF VLR subscr MSISDN:42342 usage increases to: 3
1903DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1904DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1905DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1906DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1907DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1908DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001909DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001910- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1911- ...rand=b2661531b97b12c5a2edc21a0ed16fc5
1912- ...autn=78cdd96c60840000322f421b3bb778b1
1913- ...expecting res=ed3ebf9cb6ea48ed
1914DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001915DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001916DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
1917 cm_service_result_sent == 0
1918 auth_request_sent == 1
1919- needs auth, not yet accepted
1920msc_subscr_conn_is_accepted() == false
1921 requests shall be thwarted
1922DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1923DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1924DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1925DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1926DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1927DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
1928DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1929DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
1930- MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering
1931 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1932DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1933DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1934DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 2fb4cfad)
1935DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001936DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 2fb4cfad (4 bytes)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001937DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1938DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1939DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1940DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1941DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1942DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1943DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1944DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1945DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1946DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1947DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
1948DMM -> CIPHER MODE COMMAND MSISDN:42342
1949DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
1950- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
1951- ...perm algo: 2
Neels Hofmeyr7795a192018-03-10 00:26:36 +01001952- ...key: da149b11d473f400
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001953DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001954DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001955DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
1956 cm_service_result_sent == 0
1957 cipher_mode_cmd_sent == 1
1958- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
1959 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
1960DRR MSISDN:42342: CIPHERING MODE COMPLETE
1961DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1962DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
1963DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1964DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1965DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1966DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
1967DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1968DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
1969DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1970DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001971DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1972DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001973DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1974DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001975 cm_service_result_sent == 0
1976- a USSD request is serviced
1977 expecting USSD:
1978 Your extension is 42342
1979 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
1980DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1981DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
1982DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
1983DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1984DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1985DMM USSD: Own number requested
1986DMM MSISDN:42342: MSISDN = 42342
1987DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
1988- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
1989- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001990DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1991DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01001992DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1993DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1994DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1995DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1996DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1997DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1998DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1999- BSSAP Clear --RAN_GERAN_A--> MS
2000DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
2001DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
2002DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
2003DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
2004DRLL subscr MSISDN:42342: Freeing subscriber connection
2005DREF VLR subscr MSISDN:42342 usage decreases to: 1
2006 bssap_clear_sent == 1
2007- all requests serviced, conn has been released
2008 llist_count(&net->subscr_conns) == 0
2009---
2010- an SMS is sent, MS is paged
2011DREF VLR subscr MSISDN:42342 usage increases to: 2
2012 llist_count(&vsub->cs.requests) == 0
2013DREF VLR subscr MSISDN:42342 usage increases to: 3
2014DMM Subscriber MSISDN:42342 not paged yet, start paging.
2015 RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
2016 strcmp(paging_expecting_imsi, imsi) == 0
2017DREF VLR subscr MSISDN:42342 usage increases to: 4
2018 llist_count(&vsub->cs.requests) == 1
2019DREF VLR subscr MSISDN:42342 usage decreases to: 3
2020 paging_sent == 1
2021 paging_stopped == 0
2022- the subscriber and its pending request should remain
2023DREF VLR subscr MSISDN:42342 usage increases to: 4
2024 llist_count(&vsub->cs.requests) == 1
2025DREF VLR subscr MSISDN:42342 usage decreases to: 3
2026- MS replies with Paging Response, and VLR sends *UMTS AKA* Auth Request with third key
2027 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
2028 new conn
2029DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2030DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
2031DRR PAGING RESPONSE: MI(IMSI)=901700000010650
2032DREF unknown: MSC conn use + fsm == 2 (0x5)
2033DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
2034DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
2035DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02002036DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002037DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
2038DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
2039DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
2040DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
2041DREF VLR subscr MSISDN:42342 usage increases to: 4
2042DREF VLR subscr MSISDN:42342 usage increases to: 5
2043DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
2044DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
2045DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
2046DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
2047DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
2048DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01002049DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002050- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
2051- ...rand=54d8f19778056666b41c8c25e52eb60c
2052- ...autn=53f3e5632b3d00008865dd54d49663f2
2053- ...expecting res=86e848a9e7ad8cd5
2054DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002055DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002056DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
2057 auth_request_sent == 1
2058- needs auth, not yet accepted
2059msc_subscr_conn_is_accepted() == false
2060 requests shall be thwarted
2061DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2062DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2063DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2064DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
2065DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2066DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
2067DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2068DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
2069- MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering
2070 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
2071DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
2072DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
2073DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 0ff61e0f)
2074DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01002075DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 0ff61e0f (4 bytes)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002076DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
2077DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
2078DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
2079DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2080DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
2081DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
2082DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
2083DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
2084DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
2085DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
2086DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
2087DMM -> CIPHER MODE COMMAND MSISDN:42342
2088DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
2089- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
2090- ...perm algo: 2
Neels Hofmeyr7795a192018-03-10 00:26:36 +01002091- ...key: 26ec67fad3073000
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002092DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002093DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002094DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
2095 cipher_mode_cmd_sent == 1
2096- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
2097 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
2098DRR MSISDN:42342: CIPHERING MODE COMPLETE
2099DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
2100DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
2101DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
2102DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
2103DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
2104DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
2105DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
2106DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
2107DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
2108DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002109DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
2110DPAG Paging success for MSISDN:42342 (event=0)
2111DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01002112DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002113DREF VLR subscr MSISDN:42342 usage increases to: 5
2114DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x14)
2115DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
2116- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
2117- DTAP matches expected message
2118DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002119DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
2120DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002121 dtap_tx_confirmed == 1
2122 paging_stopped == 1
2123- SMS was delivered, no requests pending for subscr
2124DREF VLR subscr MSISDN:42342 usage increases to: 5
2125 llist_count(&vsub->cs.requests) == 0
2126DREF VLR subscr MSISDN:42342 usage decreases to: 4
2127- conn is still open to wait for SMS ack dance
2128 llist_count(&net->subscr_conns) == 1
2129- MS replies with CP-ACK for received SMS
2130 MSC <--RAN_GERAN_A-- MS: SMS:0x04
2131DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
2132DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
2133DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
2134DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002135DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
2136DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002137DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
2138 llist_count(&net->subscr_conns) == 1
2139- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
2140 MSC <--RAN_GERAN_A-- MS: SMS:0x01
2141DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
2142DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2143DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
2144DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
2145- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
2146- DTAP matches expected message
2147DREF VLR subscr MSISDN:42342 usage decreases to: 3
2148DREF VLR subscr MSISDN:42342 usage decreases to: 2
2149DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002150DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
2151DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002152DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
2153DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2154DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2155DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
2156DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
2157DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
2158DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
2159- BSSAP Clear --RAN_GERAN_A--> MS
2160DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
2161DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
2162DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
2163DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
2164DRLL subscr MSISDN:42342: Freeing subscriber connection
2165DREF VLR subscr MSISDN:42342 usage decreases to: 1
2166 dtap_tx_confirmed == 1
2167 bssap_clear_sent == 1
2168- SMS is done, conn is gone
2169 llist_count(&net->subscr_conns) == 0
2170---
2171- subscriber detaches
2172 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
2173 new conn
2174DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2175DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
2176DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
2177DREF VLR subscr MSISDN:42342 usage increases to: 2
2178DMM IMSI DETACH for MSISDN:42342
2179DREF VLR subscr MSISDN:42342 usage decreases to: 1
2180DREF VLR subscr MSISDN:42342 usage decreases to: 0
2181DREF freeing VLR subscr MSISDN:42342
2182DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
2183- BSSAP Clear --RAN_GERAN_A--> MS
2184DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
2185DRLL Freeing subscriber connection with NULL subscriber
2186 bssap_clear_sent == 1
2187 llist_count(&net->subscr_conns) == 0
2188===== test_gsm_ciph_in_umts_env: SUCCESS
2189
2190full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002191talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyrcac6e892018-03-10 02:05:44 +01002192
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002193===== test_a5_3_not_supported
2194- Location Update request causes a GSUP Send Auth Info request to HLR
2195 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
2196 new conn
2197DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2198DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
2199DREF unknown: MSC conn use + fsm == 2 (0x5)
2200DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
2201DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
2202DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +02002203DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002204DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
2205DMM LU/new-LAC: 1/23
2206DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
2207DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
2208DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
2209DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
2210DREF VLR subscr unknown usage increases to: 1
2211DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
2212DVLR New subscr, IMSI: 901700000004620
2213DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2214DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2215DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
2216DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
2217DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
2218DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
2219DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
2220DVLR GSUP tx: 08010809710000004026f0
2221GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
2222DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01002223DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002224DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
2225 lu_result_sent == 0
2226- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
2227<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2228DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2229DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2230DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
2231DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
2232DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01002233DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002234- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
2235- ...rand=585df1ae287f6e273dce07090d61320b
2236- ...expecting sres=2d8b2c3e
2237DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2238<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
2239 lu_result_sent == 0
2240 auth_request_sent == 1
2241---
2242- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- alas, no matching cipher can be found, abort and release
2243 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
2244DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
2245DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
2246DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
2247DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
2248DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
2249DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
2250DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
2251DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
2252DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2253DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
2254DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
2255DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
2256DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
2257DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
2258DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
2259DMM -> CIPHER MODE COMMAND IMSI:901700000004620
2260DMSC CLASSMARK 2 unknown, assuming MS doesn't support A5/3
2261DMM IMSI:901700000004620: cannot start ciphering, no intersection between MSC-configured and MS-supported A5 algorithms
2262- ERROR sending ciphering mode command: rc=-95
2263DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Failed to send Ciphering Mode Command
2264- sending LU Reject for IMSI:901700000004620, cause 17
2265DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
2266DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002267DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
2268DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2269DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2270DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
2271DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
2272DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
2273DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
2274DMM msc_subscr_conn_close(vsub=IMSI:901700000004620, cause=2): no conn fsm, releasing directly without release event.
2275- BSSAP Clear --RAN_GERAN_A--> MS
2276DREF IMSI:901700000004620: MSC conn use - fsm == 1 (0x2)
2277DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
2278DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
2279DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
2280DRLL subscr IMSI:901700000004620: Freeing subscriber connection
2281DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
2282DREF freeing VLR subscr IMSI:901700000004620
2283 lu_result_sent == 2
2284 llist_count(&net->subscr_conns) == 0
2285===== test_a5_3_not_supported: SUCCESS
2286
2287full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002288talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra7fd88c2018-03-02 01:50:42 +01002289
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002290full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02002291talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002292