Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 3c20a5ee7483108fed857b61050b7282327d5c83 / . / tests / msc_vlr / msc_vlr_test_ss.err
blob: 15b288875ed7a3111a870c5bc6a671ed74b06e80 [file] [log] [blame]
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]1full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2talloc_total_blocks(tall_bsc_ctx) == 12
3
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]4===== test_ss_ussd_mo_geran
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]5- Location Update request causes a GSUP LU request to HLR
6 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
7 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]8DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]9DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
10DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]11DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Updated ID
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]12DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
13DMM LU/new-LAC: 1/23
14DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]15DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000004620)
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]16DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
17DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
18DREF VLR subscr unknown usage increases to: 1
19DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
20DVLR New subscr, IMSI: 901700000004620
21DREF VLR subscr IMSI:901700000004620 usage increases to: 2
22DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
23DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
24DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
25DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
26DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
27DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
28DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
29DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
30DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]31DVLR GSUP tx: 04010809710000004026f0280102
32GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0280102
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]33DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]34DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
35DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]36DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]37DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
38DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]39 lu_result_sent == 0
40- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
41<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
42DVLR GSUP rx 17: 10010809710000004026f00804036470f1
43DREF VLR subscr IMSI:901700000004620 usage increases to: 2
44DVLR IMSI:901700000004620 has MSISDN:46071
45DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
46DVLR GSUP tx: 12010809710000004026f0
47GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
48DREF VLR subscr MSISDN:46071 usage decreases to: 1
49<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
50 lu_result_sent == 0
51- HLR also sends GSUP _UPDATE_LOCATION_RESULT
52<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
53DVLR GSUP rx 11: 06010809710000004026f0
54DREF VLR subscr MSISDN:46071 usage increases to: 2
55DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
56DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
57DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
58DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
59DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
60DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
61DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
62DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
63DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
64DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
65DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
66DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
67DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
68DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
69DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
70DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
71DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
72DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
73DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
74DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
75DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
76DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
77- sending LU Accept for MSISDN:46071
78DREF VLR subscr MSISDN:46071 usage increases to: 3
79DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
80DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
81DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
82DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
83DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
84DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
85DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]86DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
87DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
88DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
89DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]90DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
91DREF VLR subscr MSISDN:46071 usage increases to: 4
92DREF VLR subscr MSISDN:46071 usage decreases to: 3
93- BSSAP Clear --RAN_GERAN_A--> MS
94DREF VLR subscr MSISDN:46071 usage decreases to: 2
95<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
96- LU was successful, and the conn has already been closed
97 lu_result_sent == 1
98 bssap_clear_sent == 1
99DREF VLR subscr MSISDN:46071 usage increases to: 3
100 vsub != NULL == 1
101 strcmp(vsub->imsi, IMSI) == 0
102 vsub->lac == 23
103DREF VLR subscr MSISDN:46071 usage decreases to: 2
104- BSS sends BSSMAP Clear Complete
105DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]106DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
107DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
108DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]109DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]110DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000004620)
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]111DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
112DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
113DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]114DRLL MSISDN:46071: Freeing RAN connection
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]115DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]116DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
117DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
118 llist_count(&net->ran_conns) == 0
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]119---
120- after a while, a new conn sends a CM Service Request
121 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
122 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]123DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]124DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
125DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
126DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]127DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_NEW}: Updated ID
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]128DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]129DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of RAN_conn(CM_SERVICE_REQ:901700000004620)
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]130DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
131DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
132DREF VLR subscr MSISDN:46071 usage increases to: 2
133DREF VLR subscr MSISDN:46071 usage increases to: 3
134DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
135DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
136DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
137DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
138DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
139DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
140DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
141DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
142DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
143DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
144- sending CM Service Accept for MSISDN:46071
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]145DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_ACCEPTED
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]146DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9: compl_l3,cm_service)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]147DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_ACCEPTED
148DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]149DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]150DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]151DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8: cm_service)
152 cm_service_result_sent == 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]153ran_conn_is_accepted() == true
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]154 MSC <--RAN_GERAN_A-- MS: GSM0480_MTYPE_REGISTER
155DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
156DRLL Dispatching 04.08 message GSM0480_MTYPE_REGISTER (0xb:0x3b)
157DMM Received SS/USSD data (trans_id=8, msg_type=GSM0480_MTYPE_REGISTER)
158DMM -> (new transaction)
159DCC (ti 08 sub MSISDN:46071 callref 20000001) New transaction
160DREF VLR subscr MSISDN:46071 usage increases to: 3
161DREF MSISDN:46071: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_nc_ss)
162DMM MSISDN:46071: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false
163DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss)
Vadim Yanitskiy8a6ef552018-06-12 08:21:20 +0700[diff] [blame]164GSUP --> HLR: OSMO_GSUP_MSGT_PROC_SS_REQUEST: 20010809710000004026f03004200000013101013515a11302010102013b300b04010f0406aa510c061b01
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]165DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
166DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Vadim Yanitskiy8a6ef552018-06-12 08:21:20 +0700[diff] [blame]167DREF MSISDN:46071: MSC conn use - dtap == 1 (0x40: trans_nc_ss)
168<-- GSUP rx OSMO_GSUP_MSGT_PROC_SS_REQUEST: 20010809710000004026f03004200000013101033527a225020101302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
169DVLR GSUP rx 61: 20010809710000004026f03004200000013101033527a225020101302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
170DREF VLR subscr MSISDN:46071 usage increases to: 4
171DMSC Routed to GSM 09.11 SS/USSD handler
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]172DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
173- DTAP --RAN_GERAN_A--> MS: GSM0480_MTYPE_RELEASE_COMPLETE: 8b2a1c27a225020101302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
174- DTAP matches expected message
Vadim Yanitskiy8a6ef552018-06-12 08:21:20 +0700[diff] [blame]175DREF VLR subscr MSISDN:46071 usage decreases to: 3
176DREF MSISDN:46071: MSC conn use - trans_nc_ss == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]177DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED
178DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]179DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Vadim Yanitskiy8a6ef552018-06-12 08:21:20 +0700[diff] [blame]180DREF VLR subscr MSISDN:46071 usage increases to: 4
181DREF VLR subscr MSISDN:46071 usage decreases to: 3
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]182- BSSAP Clear --RAN_GERAN_A--> MS
Vadim Yanitskiy8a6ef552018-06-12 08:21:20 +0700[diff] [blame]183DREF VLR subscr MSISDN:46071 usage decreases to: 2
184<-- GSUP rx OSMO_GSUP_MSGT_PROC_SS_REQUEST: vlr_gsupc_read_cb() returns 0
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]185 dtap_tx_confirmed == 1
186 bssap_clear_sent == 1
187- all requests serviced, conn has been released
188- BSS sends BSSMAP Clear Complete
189DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]190DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
191DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
192DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]193DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]194DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent RAN_conn(CM_SERVICE_REQ:901700000004620)
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]195DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
196DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]197DRLL MSISDN:46071: Freeing RAN connection
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]198DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]199DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
200DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
201 llist_count(&net->ran_conns) == 0
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]202DREF freeing VLR subscr MSISDN:46071
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]203===== test_ss_ussd_mo_geran: SUCCESS
204
205full talloc report on 'msgb' (total 0 bytes in 1 blocks)
206talloc_total_blocks(tall_bsc_ctx) == 12
207
208===== test_ss_ussd_no_geran
209- Location Update request causes a GSUP LU request to HLR
210 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
211 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]212DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]213DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
214DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]215DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Updated ID
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]216DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
217DMM LU/new-LAC: 1/23
218DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]219DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000004620)
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]220DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
221DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
222DREF VLR subscr unknown usage increases to: 1
223DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
224DVLR New subscr, IMSI: 901700000004620
225DREF VLR subscr IMSI:901700000004620 usage increases to: 2
226DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
227DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
228DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
229DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
230DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
231DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
232DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
233DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
234DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]235DVLR GSUP tx: 04010809710000004026f0280102
236GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0280102
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]237DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]238DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
239DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]240DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]241DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
242DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]243 lu_result_sent == 0
244- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
245<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
246DVLR GSUP rx 17: 10010809710000004026f00804036470f1
247DREF VLR subscr IMSI:901700000004620 usage increases to: 2
248DVLR IMSI:901700000004620 has MSISDN:46071
249DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
250DVLR GSUP tx: 12010809710000004026f0
251GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
252DREF VLR subscr MSISDN:46071 usage decreases to: 1
253<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
254 lu_result_sent == 0
255- HLR also sends GSUP _UPDATE_LOCATION_RESULT
256<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
257DVLR GSUP rx 11: 06010809710000004026f0
258DREF VLR subscr MSISDN:46071 usage increases to: 2
259DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
260DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
261DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
262DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
263DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
264DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
265DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
266DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
267DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
268DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
269DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
270DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
271DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
272DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
273DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
274DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
275DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
276DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
277DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
278DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
279DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
280DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
281- sending LU Accept for MSISDN:46071
282DREF VLR subscr MSISDN:46071 usage increases to: 3
283DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
284DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
285DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
286DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
287DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
288DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
289DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]290DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
291DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
292DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
293DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]294DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
295DREF VLR subscr MSISDN:46071 usage increases to: 4
296DREF VLR subscr MSISDN:46071 usage decreases to: 3
297- BSSAP Clear --RAN_GERAN_A--> MS
298DREF VLR subscr MSISDN:46071 usage decreases to: 2
299<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
300- LU was successful, and the conn has already been closed
301 lu_result_sent == 1
302 bssap_clear_sent == 1
303DREF VLR subscr MSISDN:46071 usage increases to: 3
304 vsub != NULL == 1
305 strcmp(vsub->imsi, IMSI) == 0
306 vsub->lac == 23
307DREF VLR subscr MSISDN:46071 usage decreases to: 2
308- BSS sends BSSMAP Clear Complete
309DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]310DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
311DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
312DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]313DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]314DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000004620)
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]315DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
316DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
317DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]318DRLL MSISDN:46071: Freeing RAN connection
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]319DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]320DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
321DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
322 llist_count(&net->ran_conns) == 0
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]323---
324- after a while, HLR initiates SS/USSD session
325DREF VLR subscr MSISDN:46071 usage increases to: 2
326 llist_count(&vsub->cs.requests) == 0
327<-- GSUP rx OSMO_GSUP_MSGT_PROC_SS_REQUEST: 20010809710000004026f03004200001013101013515a11302010102013b300b04010f0406aa510c061b01
328DVLR GSUP rx 43: 20010809710000004026f03004200001013101013515a11302010102013b300b04010f0406aa510c061b01
329DREF VLR subscr MSISDN:46071 usage increases to: 3
330DMSC Routed to GSM 09.11 SS/USSD handler
331DMM Establishing network-originated session
332DCC (ti ff sub MSISDN:46071 callref 20000101) New transaction
333DREF VLR subscr MSISDN:46071 usage increases to: 4
334DMM Triggering Paging Request
335DMM Subscriber MSISDN:46071 not paged yet, start paging.
336 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
337 strcmp(paging_expecting_imsi, imsi) == 0
338DREF VLR subscr MSISDN:46071 usage increases to: 5
339DREF VLR subscr MSISDN:46071 usage decreases to: 4
340<-- GSUP rx OSMO_GSUP_MSGT_PROC_SS_REQUEST: vlr_gsupc_read_cb() returns -22
341 llist_count(&vsub->cs.requests) == 1
342DREF VLR subscr MSISDN:46071 usage decreases to: 3
343 paging_sent == 1
344 paging_stopped == 0
345- the subscriber and its pending request should remain
346DREF VLR subscr MSISDN:46071 usage increases to: 4
347 llist_count(&vsub->cs.requests) == 1
348DREF VLR subscr MSISDN:46071 usage decreases to: 3
349- MS replies with Paging Response, we deliver the NC/USSD
350 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
351 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]352DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]353DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
354DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
355DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]356DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_NEW}: Updated ID
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]357DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]358DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of RAN_conn(PAGING_RESP:901700000004620)
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]359DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
360DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
361DREF VLR subscr MSISDN:46071 usage increases to: 4
362DREF VLR subscr MSISDN:46071 usage increases to: 5
363DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
364DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
365DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
366DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
367DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
368DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
369DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
370DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(PASSED)
371DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
372DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]373DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_ACCEPTED
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]374DPAG Paging success for MSISDN:46071 (event=0)
375DPAG Calling paging cbfn.
376DMM Paging subscr 46071 succeeded!
377DREF MSISDN:46071: MSC conn use + trans_nc_ss == 2 (0x41: compl_l3,trans_nc_ss)
378DMSC msc_tx 25 bytes to MSISDN:46071 via RAN_GERAN_A
379- DTAP --RAN_GERAN_A--> MS: GSM0480_MTYPE_REGISTER: 0b3b1c15a11302010102013b300b04010f0406aa510c061b01
380- DTAP matches expected message
381DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]382DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_ACCEPTED
383DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: connection still has active transaction: NCSS
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]384DREF VLR subscr MSISDN:46071 usage decreases to: 3
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]385DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]386DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x40: trans_nc_ss)
387 dtap_tx_confirmed == 1
388 paging_stopped == 1
389- MS responds to SS/USSD request
390 MSC <--RAN_GERAN_A-- MS: GSM0480_MTYPE_FACILITY
391DREF MSISDN:46071: MSC conn use + dtap == 2 (0x42: dtap,trans_nc_ss)
392DRLL Dispatching 04.08 message GSM0480_MTYPE_FACILITY (0xb:0x3a)
393DMM Received SS/USSD data (trans_id=0, msg_type=GSM0480_MTYPE_FACILITY)
394GSUP --> HLR: OSMO_GSUP_MSGT_PROC_SS_REQUEST: 20010809710000004026f03004200001013101023527a225020101302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]395DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
396DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]397DREF MSISDN:46071: MSC conn use - dtap == 1 (0x40: trans_nc_ss)
398 dtap_tx_confirmed == 1
399 paging_stopped == 1
400- HLR terminates the session
401<-- GSUP rx OSMO_GSUP_MSGT_PROC_SS_REQUEST: 20010809710000004026f0300420000101310103
402DVLR GSUP rx 20: 20010809710000004026f0300420000101310103
403DREF VLR subscr MSISDN:46071 usage increases to: 4
404DMSC Routed to GSM 09.11 SS/USSD handler
405DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
406- DTAP --RAN_GERAN_A--> MS: GSM0480_MTYPE_RELEASE_COMPLETE: 0b2a
407- DTAP matches expected message
408DREF VLR subscr MSISDN:46071 usage decreases to: 3
409DREF MSISDN:46071: MSC conn use - trans_nc_ss == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]410DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED
411DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]412DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
413DREF VLR subscr MSISDN:46071 usage increases to: 4
414DREF VLR subscr MSISDN:46071 usage decreases to: 3
415- BSSAP Clear --RAN_GERAN_A--> MS
416DREF VLR subscr MSISDN:46071 usage decreases to: 2
417<-- GSUP rx OSMO_GSUP_MSGT_PROC_SS_REQUEST: vlr_gsupc_read_cb() returns 0
418 dtap_tx_confirmed == 1
419 bssap_clear_sent == 1
420- all requests serviced, conn has been released
421- BSS sends BSSMAP Clear Complete
422DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]423DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
424DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
425DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]426DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]427DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent RAN_conn(PAGING_RESP:901700000004620)
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]428DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
429DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]430DRLL MSISDN:46071: Freeing RAN connection
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]431DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]432DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
433DMM RAN_conn(PAGING_RESP:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
434 llist_count(&net->ran_conns) == 0
Vadim Yanitskiyf2f83b02018-06-17 21:09:28 +0700[diff] [blame]435DREF freeing VLR subscr MSISDN:46071
436===== test_ss_ussd_no_geran: SUCCESS
Vadim Yanitskiy27605852018-06-15 23:57:30 +0700[diff] [blame]437
438full talloc report on 'msgb' (total 0 bytes in 1 blocks)
439talloc_total_blocks(tall_bsc_ctx) == 12
440
441full talloc report on 'msgb' (total 0 bytes in 1 blocks)
442talloc_total_blocks(tall_bsc_ctx) == 12
443