Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 7916ca1c2d53c7447608700705fae9ef49c81c28 / . / tests / msc_vlr / msc_vlr_test_ms_timeout.err
blob: c91f6a23e8680106ce5d08714fced22dd431a64b [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]2talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]4===== test_ms_timeout_lu_auth_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]5- Total time passed: 0.000000 s
6- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]7 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]8 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]9DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]10DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]11DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]12DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]13DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]14DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]15DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]16DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]17DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
18DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]19DREF VLR subscr unknown usage increases to: 1
20DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
21DVLR New subscr, IMSI: 901700000004620
22DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]23DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]24DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
25DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
26DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
27DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000004620)
28DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]29DVLR GSUP tx: 08010809710000004026f0
30GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]31DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]32DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
33DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]34DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]35DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
36DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]37 lu_result_sent == 0
38- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
39<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
40DVLR GSUP rx 47: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
41DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]42DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]43DVLR SUBSCR(IMSI:901700000004620) Received 1 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]44DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
45DVLR VLR_Authenticate(LU: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 +0100[diff] [blame]46- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
47- ...rand=585df1ae287f6e273dce07090d61320b
48- ...expecting sres=2d8b2c3e
49DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
50<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
51 auth_request_sent == 1
52 lu_result_sent == 0
53---
54- MS fails to send an Authentication Response
55- At first, we're still waiting
56- Total time passed: 0.000423 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]57 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]58 lu_result_sent == 0
59- Total time passed: 1.000658 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]60 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]61 lu_result_sent == 0
62- Total time passed: 2.000893 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]63 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]64 lu_result_sent == 0
65- Total time passed: 3.001128 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]66 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]67 lu_result_sent == 0
68- Total time passed: 4.001363 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]69 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]70 lu_result_sent == 0
71- Total time passed: 5.001598 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]72DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Timeout of T0
73DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_CN_CLOSE
74DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Close event, cause: CONGESTION
75DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]76DREF IMSI:901700000004620: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyr3bae8362017-11-18 23:26:24 +0100[diff] [blame]77DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]78- sending LU Reject for IMSI:901700000004620, cause 22
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]79DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]80DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_CN_CLOSE
81DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Event RAN_CONN_E_CN_CLOSE not permitted
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]82DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
83- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]84- RAN_CONN_TIMEOUT has passed, conn is gone.
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]85 bssap_clear_sent == 1
86- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]87DREF IMSI:901700000004620: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]88DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
89DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
90DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]91DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
92DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
93DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Removing from parent vlr_lu_fsm(LU:901700000004620)
94DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Freeing instance
95DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]96DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]97DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
98DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
99DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]100DRLL IMSI:901700000004620: Freeing RAN connection
Neels Hofmeyr3bae8362017-11-18 23:26:24 +0100[diff] [blame]101DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
102DREF freeing VLR subscr IMSI:901700000004620
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]103DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
104DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
105 llist_count(&net->ran_conns) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]106 lu_result_sent == 2
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]107===== test_ms_timeout_lu_auth_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]108
109full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]110talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]111
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]112===== test_ms_timeout_cm_auth_resp
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]113- Total time passed: 0.000000 s
114- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]115 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]116 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]117DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]118DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]119DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]120DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]121DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]122DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]123DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]124DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]125DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
126DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]127DREF VLR subscr unknown usage increases to: 1
128DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
129DVLR New subscr, IMSI: 901700000004620
130DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]131DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]132DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
133DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
134DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
135DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000004620)
136DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]137DVLR GSUP tx: 08010809710000004026f0
138GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]139DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]140DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
141DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]142DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]143DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
144DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]145 lu_result_sent == 0
146- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
147<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
148DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
149DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]150DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]151DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]152DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
153DVLR VLR_Authenticate(LU: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 +0100[diff] [blame]154- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
155- ...rand=585df1ae287f6e273dce07090d61320b
156- ...expecting sres=2d8b2c3e
157DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
158<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
159 auth_request_sent == 1
160 lu_result_sent == 0
161- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]162 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]163DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]164DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]165DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]166DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]167DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]168DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]169DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]170DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
171DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
172DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000004620)
173DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
174DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
175DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
176DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
177DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
178DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
179DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
180DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
181DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
182DVLR 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]183DVLR GSUP tx: 04010809710000004026f0280102
184GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]185DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]186DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]187DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
188DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]189 lu_result_sent == 0
190- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
191<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
192DVLR GSUP rx 17: 10010809710000004026f00804036470f1
193DREF VLR subscr IMSI:901700000004620 usage increases to: 2
194DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]195DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]196DVLR GSUP tx: 12010809710000004026f0
197GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
198DREF VLR subscr MSISDN:46071 usage decreases to: 1
199<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
200 lu_result_sent == 0
201- HLR also sends GSUP _UPDATE_LOCATION_RESULT
202<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
203DVLR GSUP rx 11: 06010809710000004026f0
204DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]205DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
206DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
207DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
208DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
209DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
210DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
211DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
212DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
213DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
214DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
215DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
216DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
217DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]218DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]219- sending LU Accept for MSISDN:46071
220DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]221DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
222DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
223DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
224DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
225DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
226DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
227DVLR 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]228DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
229DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
230DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
231DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]232DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]233DREF VLR subscr MSISDN:46071 usage increases to: 4
234DREF VLR subscr MSISDN:46071 usage decreases to: 3
235- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]236DREF VLR subscr MSISDN:46071 usage decreases to: 2
237<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
238 bssap_clear_sent == 1
239- LU was successful, and the conn has already been closed
240 lu_result_sent == 1
241- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]242DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]243DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
244DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
245DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]246DVLR 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]247DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]248DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
249DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
250DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]251DRLL MSISDN:46071: Freeing RAN connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]252DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]253DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
254DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
255 llist_count(&net->ran_conns) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]256---
257- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]258 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]259 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]260DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]261DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]262DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]263DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]264DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]265DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]266DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of RAN_conn(CM_SERVICE_REQ:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]267DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
268DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]269DREF VLR subscr MSISDN:46071 usage increases to: 2
270DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]271DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
272DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
273DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
274DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620)
275DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
276DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
277DVLR VLR_Authenticate(CM_SERVICE_REQ: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 +0100[diff] [blame]278- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
279- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
280- ...expecting sres=20bde240
281DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]282DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
283DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]284DREF MSISDN:46071: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]285DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
286DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]287 cm_service_result_sent == 0
288 auth_request_sent == 1
289---
290- MS fails to send an Authentication Response
291- At first, we're still waiting
292- Total time passed: 0.000423 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]293 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]294 cm_service_result_sent == 0
295- Total time passed: 1.000658 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]296 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]297 cm_service_result_sent == 0
298- Total time passed: 2.000893 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]299 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]300 cm_service_result_sent == 0
301- Total time passed: 3.001128 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]302 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]303 cm_service_result_sent == 0
304- Total time passed: 4.001363 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]305 llist_count(&net->ran_conns) == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]306 cm_service_result_sent == 0
307- Total time passed: 5.001598 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]308DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_AUTH_CIPH}: Timeout of T0
309DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_CN_CLOSE
310DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_AUTH_CIPH}: Close event, cause: CONGESTION
311DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]312DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyr3bae8362017-11-18 23:26:24 +0100[diff] [blame]313DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]314DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: Cancel: OSMO_FSM_TERM_ERROR
315DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(CONGESTION)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]316DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]317DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: CONGESTION
318- sending CM Service Reject for MSISDN:46071, cause: CONGESTION
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]319DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_CN_CLOSE
320DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASING}: Event RAN_CONN_E_CN_CLOSE not permitted
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]321DREF VLR subscr MSISDN:46071 usage decreases to: 2
322- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]323- RAN_CONN_TIMEOUT has passed, conn is gone.
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]324 bssap_clear_sent == 1
325- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]326DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]327DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
328DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
329DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]330DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
331DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
332DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620)
333DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Freeing instance
334DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]335DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent RAN_conn(CM_SERVICE_REQ:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]336DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
337DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]338DRLL MSISDN:46071: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]339DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]340DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
341DMM RAN_conn(CM_SERVICE_REQ:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
342 llist_count(&net->ran_conns) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]343 cm_service_result_sent == 2
344DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]345===== test_ms_timeout_cm_auth_resp: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]346
347full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]348talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]349
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]350===== test_ms_timeout_paging
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]351- Total time passed: 0.000000 s
352- Location Update request causes a GSUP LU request to HLR
353 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
354 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]355DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]356DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]357DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]358DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]359DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
360DMM LU/new-LAC: 1/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]361DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]362DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]363DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
364DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]365DREF VLR subscr unknown usage increases to: 1
366DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
367DVLR New subscr, IMSI: 901700000004620
368DREF VLR subscr IMSI:901700000004620 usage increases to: 2
369DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]370DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
371DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
372DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
373DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
374DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
375DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
376DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
377DVLR 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]378DVLR GSUP tx: 04010809710000004026f0280102
379GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]380DVLR 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]381DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
382DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]383DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]384DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
385DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]386 lu_result_sent == 0
387- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
388<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
389DVLR GSUP rx 17: 10010809710000004026f00804036470f1
390DREF VLR subscr IMSI:901700000004620 usage increases to: 2
391DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]392DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]393DVLR GSUP tx: 12010809710000004026f0
394GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
395DREF VLR subscr MSISDN:46071 usage decreases to: 1
396<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
397 lu_result_sent == 0
398- HLR also sends GSUP _UPDATE_LOCATION_RESULT
399<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
400DVLR GSUP rx 11: 06010809710000004026f0
401DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]402DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
403DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
404DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
405DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
406DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
407DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
408DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
409DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
410DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
411DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
412DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
413DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
414DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]415DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]416- sending LU Accept for MSISDN:46071
417DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]418DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
419DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
420DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
421DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
422DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
423DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
424DVLR 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]425DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
426DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
427DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
428DMM RAN_conn(LU:901700000004620){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]429DREF MSISDN:46071: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]430DREF VLR subscr MSISDN:46071 usage increases to: 4
431DREF VLR subscr MSISDN:46071 usage decreases to: 3
432- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]433DREF VLR subscr MSISDN:46071 usage decreases to: 2
434<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
435- LU was successful, and the conn has already been closed
436 lu_result_sent == 1
437 bssap_clear_sent == 1
438- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]439DREF MSISDN:46071: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]440DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
441DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
442DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]443DVLR 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]444DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000004620)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]445DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
446DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
447DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]448DRLL MSISDN:46071: Freeing RAN connection
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]449DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]450DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
451DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
452 llist_count(&net->ran_conns) == 0
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]453---
454- an SMS is sent, MS is paged
455DREF VLR subscr MSISDN:46071 usage increases to: 2
456 llist_count(&vsub->cs.requests) == 0
457DREF VLR subscr MSISDN:46071 usage increases to: 3
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]458DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
459DREF VLR subscr MSISDN:46071 usage increases to: 4
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]460DMM Subscriber MSISDN:46071 not paged yet, start paging.
461 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
462 strcmp(paging_expecting_imsi, imsi) == 0
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]463DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]464 llist_count(&vsub->cs.requests) == 1
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]465DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]466 paging_sent == 1
467 paging_stopped == 0
468- time passes and no paging result is received
469- Total time passed: 9.000000 s
470- the paging timeout has not yet expired
471 paging_stopped == 0
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]472DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]473 vsub->cs.is_paging == 1
474- another request is added to the list but does not cause another paging
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]475DREF VLR subscr MSISDN:46071 usage increases to: 6
476DCC (ti 01 sub MSISDN:46071 callref 40000002) New transaction
477DREF VLR subscr MSISDN:46071 usage increases to: 7
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]478DMM Subscriber MSISDN:46071 already paged.
479 llist_count(&vsub->cs.requests) == 2
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]480DREF VLR subscr MSISDN:46071 usage decreases to: 6
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]481 paging_sent == 0
482- the paging timeout expires, the paging as well as the requests are canceled
483- Total time passed: 11.000000 s
484DPAG Paging failure for MSISDN:46071 (event=1)
485DPAG Calling paging cbfn.
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]486DREF VLR subscr MSISDN:46071 usage decreases to: 5
487DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]488DPAG Calling paging cbfn.
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]489DREF VLR subscr MSISDN:46071 usage decreases to: 3
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]490DREF VLR subscr MSISDN:46071 usage decreases to: 2
491DREF VLR subscr MSISDN:46071 usage decreases to: 1
492 paging_stopped == 1
493DREF VLR subscr MSISDN:46071 usage increases to: 2
494 vsub->cs.is_paging == 0
495 llist_count(&vsub->cs.requests) == 0
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]496---
Neels Hofmeyrfacd57a2017-12-15 03:48:48 +0100[diff] [blame]497- Now that the timeout has expired, another Paging is sent on request
498DREF VLR subscr MSISDN:46071 usage increases to: 3
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]499DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
500DREF VLR subscr MSISDN:46071 usage increases to: 4
Neels Hofmeyrfacd57a2017-12-15 03:48:48 +0100[diff] [blame]501DMM Subscriber MSISDN:46071 not paged yet, start paging.
502 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
503 strcmp(paging_expecting_imsi, imsi) == 0
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]504DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyrfacd57a2017-12-15 03:48:48 +0100[diff] [blame]505 llist_count(&vsub->cs.requests) == 1
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]506DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfacd57a2017-12-15 03:48:48 +0100[diff] [blame]507 paging_sent == 1
508 paging_stopped == 0
509---
510- subscriber detaches, pagings are canceled
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]511 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
512 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]513DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]514DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]515DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
516DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]517DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]518DMM IMSI DETACH for MSISDN:46071
Neels Hofmeyrfacd57a2017-12-15 03:48:48 +0100[diff] [blame]519DPAG Paging failure for MSISDN:46071 (event=1)
520DPAG Calling paging cbfn.
Vadim Yanitskiy24e025e2018-11-22 15:42:39 +0700[diff] [blame]521DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyrfacd57a2017-12-15 03:48:48 +0100[diff] [blame]522DREF VLR subscr MSISDN:46071 usage decreases to: 3
523DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]524DREF VLR subscr MSISDN:46071 usage increases to: 3
525DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]526DREF VLR subscr MSISDN:46071 usage decreases to: 1
527DREF VLR subscr MSISDN:46071 usage decreases to: 0
528DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]529DMM RAN_conn{RAN_CONN_S_NEW}: Received Event RAN_CONN_E_CN_CLOSE
530DMM RAN_conn{RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]531DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release)
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]532- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]533DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]534 bssap_clear_sent == 1
535 paging_stopped == 1
536- BSS sends BSSMAP Clear Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]537DREF unknown: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]538DMM RAN_conn{RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
539DMM RAN_conn{RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
540DMM RAN_conn{RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
541DRLL Freeing RAN connection with NULL subscriber
542DMM RAN_conn{RAN_CONN_S_RELEASED}: Freeing instance
543DMM RAN_conn{RAN_CONN_S_RELEASED}: Deallocated
544 llist_count(&net->ran_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]545===== test_ms_timeout_paging: SUCCESS
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]546
547full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]548talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr2ff5bcd2017-12-15 03:02:27 +0100[diff] [blame]549
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]550===== test_classmark_update_timeout
551- Total time passed: 0.000000 s
552- Location Update request causes a GSUP Send Auth Info request to HLR
553 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
554 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]555DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]556DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
557DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]558DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]559DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
560DMM LU/new-LAC: 1/23
561DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]562DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000004620)
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]563DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
564DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
565DREF VLR subscr unknown usage increases to: 1
566DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
567DVLR New subscr, IMSI: 901700000004620
568DREF VLR subscr IMSI:901700000004620 usage increases to: 2
569DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
570DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
571DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
572DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
573DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000004620)
574DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
575DVLR GSUP tx: 08010809710000004026f0
576GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
577DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]578DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
579DMM RAN_conn(LU:901700000004620){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]580DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]581DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
582DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]583 lu_result_sent == 0
584- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
585<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
586DVLR GSUP rx 47: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
587DREF VLR subscr IMSI:901700000004620 usage increases to: 2
588DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
589DVLR SUBSCR(IMSI:901700000004620) Received 1 auth tuples
590DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
591DVLR VLR_Authenticate(LU: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)
592- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
593- ...rand=585df1ae287f6e273dce07090d61320b
594- ...expecting sres=2d8b2c3e
595DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
596<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
597 lu_result_sent == 0
598 auth_request_sent == 1
599---
600- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- but needs Classmark 2 to determine whether A5/3 is supported
601 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
602DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
603DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
604DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
605DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
606DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
607DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
608DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
609DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
610DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
611DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000004620)
612DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
613DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
614DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
615DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
616DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
617DMM IMSI:901700000004620: to determine whether A5/3 is supported, first ask for a Classmark Update to obtain Classmark 2
618 BSC <--BSSAP-BSS-MANAGEMENT-- MSC: CLASSMARK REQ [L3]> 00 01 58
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]619DMM RAN_conn(LU:901700000004620){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_WAIT_CLASSMARK_UPDATE
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]620DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
621DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]622DMM RAN_conn(LU:901700000004620){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event RAN_CONN_E_UNUSED
623DMM RAN_conn(LU:901700000004620){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]624 lu_result_sent == 0
625---
626- But the BSSMAP Classmark Update never arrives
627- At first, we're still waiting
628- Total time passed: 0.000423 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]629 llist_count(&net->ran_conns) == 1
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]630 lu_result_sent == 0
631- Total time passed: 1.000658 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]632 llist_count(&net->ran_conns) == 1
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]633 lu_result_sent == 0
634- Total time passed: 2.000893 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]635 llist_count(&net->ran_conns) == 1
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]636 lu_result_sent == 0
637- Total time passed: 3.001128 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]638 llist_count(&net->ran_conns) == 1
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]639 lu_result_sent == 0
640- Total time passed: 4.001363 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]641 llist_count(&net->ran_conns) == 1
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]642 lu_result_sent == 0
643- Total time passed: 5.001598 s
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]644DMM RAN_conn(LU:901700000004620){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Timeout of T0
645DMM RAN_conn(LU:901700000004620){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event RAN_CONN_E_CN_CLOSE
646DMM RAN_conn(LU:901700000004620){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Close event, cause: CONGESTION
647DMM RAN_conn(LU:901700000004620){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]648DREF IMSI:901700000004620: MSC conn use + release == 1 (0x100: release)
649DREF VLR subscr IMSI:901700000004620 usage increases to: 2
650- sending LU Reject for IMSI:901700000004620, cause 22
651DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]652DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_CN_CLOSE
653DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Event RAN_CONN_E_CN_CLOSE not permitted
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]654DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
655- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]656- RAN_CONN_TIMEOUT has passed, conn is gone.
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]657 bssap_clear_sent == 1
658- BSS sends BSSMAP Clear Complete
659DREF IMSI:901700000004620: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]660DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
661DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
662DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]663DVLR 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]664DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000004620)
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]665DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
666DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
667DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]668DRLL IMSI:901700000004620: Freeing RAN connection
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]669DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
670DREF freeing VLR subscr IMSI:901700000004620
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]671DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Freeing instance
672DMM RAN_conn(LU:901700000004620){RAN_CONN_S_RELEASED}: Deallocated
673 llist_count(&net->ran_conns) == 0
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]674 lu_result_sent == 2
675===== test_classmark_update_timeout: SUCCESS
676
677full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]678talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr3117b702018-09-13 03:23:07 +0200[diff] [blame]679
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]680full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]681talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]682