summaryrefslogtreecommitdiffstats
path: root/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
diff options
context:
space:
mode:
authorNeels Hofmeyr <nhofmeyr@sysmocom.de>2016-05-20 21:59:55 +0200
committerNeels Hofmeyr <nhofmeyr@sysmocom.de>2017-06-18 17:49:00 +0200
commit61692adb2b0cd090c8fb8c81376a28bca099d079 (patch)
treebee3b3fde06ec8dc2a4cb9208ceae3465cea25a5 /openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
parent58774cba12ec4675e32fa524cfa631bdc690a9da (diff)
Implement IuCS (large refactoring and addition)
osmo-nitb becomes osmo-msc add DIUCS debug log constant add iucs.[hc] add msc vty, remove nitb vty add libiudummy, to avoid linking Iu deps in tests Use new msc_tx_dtap() instead of gsm0808_submit_dtap() libmgcp: add mgcpgw client API bridge calls via mgcpgw mgcp: hack RAB success from nano3G: patch first RTP payload The ip.access nano3G needs the first RTP payload's first two bytes to read hex 'e400', or it will reject the RAB assignment. Add flag patched_first_rtp_payload to mgcp_rtp_state to detect the first RTP payload on a stream, and overwrite its first bytes with e400. This should probably be configurable, but seems to not harm other femto cells (as long as we patch only the first RTP payload in each stream). Only do this when sending to the BTS side. Change-Id: Ie13ff348117e892d41b8355ab6c24915301eaeaf
Diffstat (limited to 'openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err')
-rw-r--r--openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err345
1 files changed, 187 insertions, 158 deletions
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err b/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
index a50fa7cc8..61f07e755 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
@@ -5,9 +5,9 @@
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
@@ -27,7 +27,7 @@ DVLR GSUP tx: 08010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
-DMM compl_l3: Keeping conn
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
@@ -63,6 +63,7 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
- sending Ciphering Mode Command for IMSI:901700000004620: cipher=VLR_CIPH_A5_1 kc=61855fb81fc2a800 retrieve_imeisv=0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- needs ciph, not yet accepted
@@ -136,12 +137,13 @@ DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from paren
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
@@ -150,8 +152,8 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF VLR subscr MSISDN:46071 usage decreases to: 1
<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
- LU was successful, and the conn has already been closed
@@ -165,9 +167,9 @@ DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
@@ -185,7 +187,7 @@ DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: us
- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
- ...expecting sres=20bde240
DREF VLR subscr MSISDN:46071 usage decreases to: 2
-DMM compl_l3: Keeping conn
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
auth_request_sent == 1
cm_service_result_sent == 0
@@ -219,6 +221,7 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AU
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
- sending Ciphering Mode Command for MSISDN:46071: cipher=VLR_CIPH_A5_1 kc=07fa7502e07e1c00 retrieve_imeisv=0
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
cm_service_result_sent == 0
cipher_mode_cmd_sent == 1
@@ -245,11 +248,12 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
cm_service_result_sent == 0
- a USSD request is serviced
expecting USSD:
@@ -258,22 +262,24 @@ DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR
DREF MSISDN:46071: MSC conn use + 1 == 2
DRLL Dispatching 04.08 message, pdisc=11
DMM MSISDN:46071 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
DMM USSD: Own number requested
DMM MSISDN:46071: MSISDN = 46071
-- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
+DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
- DTAP matches expected message
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -284,10 +290,9 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage increases to: 2
llist_count(&vsub->cs.requests) == 0
DREF VLR subscr MSISDN:46071 usage increases to: 3
-DMM Subscriber MSISDN:46071 not paged yet.
- BTS/BSC sends out paging request to IMSI:901700000004620 for channel type 1
- strcmp(paging_expecting_imsi, sub->imsi) == 0
-DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
+DMM Subscriber MSISDN:46071 not paged yet, start paging.
+ RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 0
+ strcmp(paging_expecting_imsi, imsi) == 0
DREF VLR subscr MSISDN:46071 usage increases to: 4
llist_count(&vsub->cs.requests) == 1
DREF VLR subscr MSISDN:46071 usage decreases to: 3
@@ -304,9 +309,9 @@ DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=6
DRR PAGING RESPONSE: MI(IMSI)=901700000004620
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
@@ -324,7 +329,7 @@ DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: us
- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
- ...expecting sres=a29514ae
DREF VLR subscr MSISDN:46071 usage decreases to: 4
-DMM compl_l3: Keeping conn
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
auth_request_sent == 1
- needs auth, not yet accepted
@@ -357,6 +362,7 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AU
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
- sending Ciphering Mode Command for MSISDN:46071: cipher=VLR_CIPH_A5_1 kc=e2b234f807886400 retrieve_imeisv=0
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
cipher_mode_cmd_sent == 1
- needs ciph, not yet accepted
@@ -382,16 +388,19 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DPAG Paging success for MSISDN:46071 (event=0)
+DPAG Calling paging cbfn.
DREF VLR subscr MSISDN:46071 usage increases to: 5
DREF MSISDN:46071: MSC conn use + 1 == 2
-- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
+DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
- DTAP matches expected message
DREF VLR subscr MSISDN:46071 usage decreases to: 4
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
dtap_tx_confirmed == 1
paging_stopped == 1
- SMS was delivered, no requests pending for subscr
@@ -404,31 +413,34 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 4
rx from MS: pdisc=0x89 msg_type=0x04
DREF MSISDN:46071: MSC conn use + 1 == 3
DRLL Dispatching 04.08 message, pdisc=9
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_SMS
DREF MSISDN:46071: MSC conn use - 1 == 2
llist_count(&net->subscr_conns) == 1
- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
rx from MS: pdisc=0x89 msg_type=0x01
DREF MSISDN:46071: MSC conn use + 1 == 3
DRLL Dispatching 04.08 message, pdisc=9
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
-- DTAP --> MS: 0904
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 0904
- DTAP matches expected message
DREF VLR subscr MSISDN:46071 usage decreases to: 3
DREF VLR subscr MSISDN:46071 usage decreases to: 2
DREF MSISDN:46071: MSC conn use - 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -447,14 +459,13 @@ DMM Subscriber MSISDN:46071 DETACHED
DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage decreases to: 0
DREF freeing VLR subscr MSISDN:46071
-DMM No conn_fsm, release conn
-DMM compl_l3: Discarding conn
+DREF unknown: MSC conn use - 1 == 0
DRLL Freeing subscriber connection with NULL subscriber
llist_count(&net->subscr_conns) == 0
===== test_ciph: SUCCESS
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
-talloc_total_blocks(tall_bsc_ctx) == 75
+talloc_total_blocks(tall_bsc_ctx) == 9
===== test_ciph_tmsi
- Location Update request causes a GSUP Send Auth Info request to HLR
@@ -463,9 +474,9 @@ talloc_total_blocks(tall_bsc_ctx) == 75
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
@@ -485,7 +496,7 @@ DVLR GSUP tx: 08010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
-DMM compl_l3: Keeping conn
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
@@ -521,6 +532,7 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
- sending Ciphering Mode Command for IMSI:901700000004620: cipher=VLR_CIPH_A5_1 kc=61855fb81fc2a800 retrieve_imeisv=0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
auth_request_sent == 1
@@ -626,20 +638,21 @@ DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from paren
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -660,9 +673,9 @@ DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
@@ -680,7 +693,7 @@ DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count
- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
- ...expecting sres=20bde240
DREF VLR subscr MSISDN:46071 usage decreases to: 2
-DMM compl_l3: Keeping conn
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
auth_request_sent == 1
cm_service_result_sent == 0
@@ -714,6 +727,7 @@ DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
- sending Ciphering Mode Command for MSISDN:46071: cipher=VLR_CIPH_A5_1 kc=07fa7502e07e1c00 retrieve_imeisv=0
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
cm_service_result_sent == 0
cipher_mode_cmd_sent == 1
@@ -740,11 +754,12 @@ DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_pos
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
cm_service_result_sent == 0
- a USSD request is serviced
expecting USSD:
@@ -753,22 +768,24 @@ DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E
DREF MSISDN:46071: MSC conn use + 1 == 2
DRLL Dispatching 04.08 message, pdisc=11
DMM MSISDN:46071 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
DMM USSD: Own number requested
DMM MSISDN:46071: MSISDN = 46071
-- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
+DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
- DTAP matches expected message
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -779,10 +796,9 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage increases to: 2
llist_count(&vsub->cs.requests) == 0
DREF VLR subscr MSISDN:46071 usage increases to: 3
-DMM Subscriber MSISDN:46071 not paged yet.
- BTS/BSC sends out paging request to IMSI:901700000004620 for channel type 1
+DMM Subscriber MSISDN:46071 not paged yet, start paging.
+ RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 0
paging_expecting_tmsi == 0x03020100
-DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
DREF VLR subscr MSISDN:46071 usage increases to: 4
llist_count(&vsub->cs.requests) == 1
DREF VLR subscr MSISDN:46071 usage decreases to: 3
@@ -799,9 +815,9 @@ DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=6
DRR PAGING RESPONSE: MI(TMSI)=50462976
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
@@ -819,7 +835,7 @@ DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count
- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
- ...expecting sres=a29514ae
DREF VLR subscr MSISDN:46071 usage decreases to: 4
-DMM compl_l3: Keeping conn
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
auth_request_sent == 1
- needs auth, not yet accepted
@@ -852,6 +868,7 @@ DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
- sending Ciphering Mode Command for MSISDN:46071: cipher=VLR_CIPH_A5_1 kc=e2b234f807886400 retrieve_imeisv=0
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
cipher_mode_cmd_sent == 1
- needs ciph, not yet accepted
@@ -877,16 +894,19 @@ DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_pos
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DPAG Paging success for MSISDN:46071 (event=0)
+DPAG Calling paging cbfn.
DREF VLR subscr MSISDN:46071 usage increases to: 5
DREF MSISDN:46071: MSC conn use + 1 == 2
-- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
+DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
- DTAP matches expected message
DREF VLR subscr MSISDN:46071 usage decreases to: 4
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
dtap_tx_confirmed == 1
paging_stopped == 1
- SMS was delivered, no requests pending for subscr
@@ -899,31 +919,34 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 4
rx from MS: pdisc=0x89 msg_type=0x04
DREF MSISDN:46071: MSC conn use + 1 == 3
DRLL Dispatching 04.08 message, pdisc=9
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_SMS
DREF MSISDN:46071: MSC conn use - 1 == 2
llist_count(&net->subscr_conns) == 1
- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
rx from MS: pdisc=0x89 msg_type=0x01
DREF MSISDN:46071: MSC conn use + 1 == 3
DRLL Dispatching 04.08 message, pdisc=9
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
-- DTAP --> MS: 0904
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 0904
- DTAP matches expected message
DREF VLR subscr MSISDN:46071 usage decreases to: 3
DREF VLR subscr MSISDN:46071 usage decreases to: 2
DREF MSISDN:46071: MSC conn use - 1 == 2
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -942,14 +965,13 @@ DMM Subscriber MSISDN:46071 DETACHED
DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage decreases to: 0
DREF freeing VLR subscr MSISDN:46071
-DMM No conn_fsm, release conn
-DMM compl_l3: Discarding conn
+DREF unknown: MSC conn use - 1 == 0
DRLL Freeing subscriber connection with NULL subscriber
llist_count(&net->subscr_conns) == 0
===== test_ciph_tmsi: SUCCESS
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
-talloc_total_blocks(tall_bsc_ctx) == 75
+talloc_total_blocks(tall_bsc_ctx) == 9
===== test_ciph_imei
- Location Update request causes a GSUP Send Auth Info request to HLR
@@ -958,9 +980,9 @@ talloc_total_blocks(tall_bsc_ctx) == 75
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
@@ -980,7 +1002,7 @@ DVLR GSUP tx: 08010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
-DMM compl_l3: Keeping conn
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
@@ -1016,6 +1038,7 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
- sending Ciphering Mode Command for IMSI:901700000004620: cipher=VLR_CIPH_A5_1 kc=61855fb81fc2a800 retrieve_imeisv=0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- needs ciph, not yet accepted
@@ -1081,7 +1104,8 @@ DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI
-- DTAP --> MS: 051802
+DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 051802
- DTAP matches expected message
DREF VLR subscr MSISDN:46071 usage decreases to: 1
<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
@@ -1117,20 +1141,21 @@ DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from paren
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -1153,14 +1178,13 @@ DMM Subscriber MSISDN:46071 DETACHED
DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage decreases to: 0
DREF freeing VLR subscr MSISDN:46071
-DMM No conn_fsm, release conn
-DMM compl_l3: Discarding conn
+DREF unknown: MSC conn use - 1 == 0
DRLL Freeing subscriber connection with NULL subscriber
llist_count(&net->subscr_conns) == 0
===== test_ciph_imei: SUCCESS
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
-talloc_total_blocks(tall_bsc_ctx) == 75
+talloc_total_blocks(tall_bsc_ctx) == 9
===== test_ciph_imeisv
- Location Update request causes a GSUP Send Auth Info request to HLR
@@ -1169,9 +1193,9 @@ talloc_total_blocks(tall_bsc_ctx) == 75
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
@@ -1191,7 +1215,7 @@ DVLR GSUP tx: 08010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
-DMM compl_l3: Keeping conn
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
@@ -1227,6 +1251,7 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
- sending Ciphering Mode Command for IMSI:901700000004620: cipher=VLR_CIPH_A5_1 kc=61855fb81fc2a800 retrieve_imeisv=1
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
cipher_mode_cmd_sent == 1
cipher_mode_cmd_sent_with_imeisv == 1
@@ -1284,6 +1309,7 @@ DMM IDENTITY RESPONSE: MI(IMEI)=423423423423423
DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423423
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_ID_IMEI
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Event VLR_ULA_E_ID_IMEI not permitted
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
@@ -1330,12 +1356,13 @@ DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from paren
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
@@ -1344,8 +1371,8 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF VLR subscr MSISDN:46071 usage decreases to: 1
<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
- LU was successful, and the conn has already been closed
@@ -1363,14 +1390,13 @@ DMM Subscriber MSISDN:46071 DETACHED
DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage decreases to: 0
DREF freeing VLR subscr MSISDN:46071
-DMM No conn_fsm, release conn
-DMM compl_l3: Discarding conn
+DREF unknown: MSC conn use - 1 == 0
DRLL Freeing subscriber connection with NULL subscriber
llist_count(&net->subscr_conns) == 0
===== test_ciph_imeisv: SUCCESS
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
-talloc_total_blocks(tall_bsc_ctx) == 75
+talloc_total_blocks(tall_bsc_ctx) == 9
===== test_ciph_tmsi_imei
- Location Update request causes a GSUP Send Auth Info request to HLR
@@ -1379,9 +1405,9 @@ talloc_total_blocks(tall_bsc_ctx) == 75
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message, pdisc=5
DREF unknown: MSC conn use + 1 == 2
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
@@ -1401,7 +1427,7 @@ DVLR GSUP tx: 08010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
-DMM compl_l3: Keeping conn
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
@@ -1437,6 +1463,7 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
- sending Ciphering Mode Command for IMSI:901700000004620: cipher=VLR_CIPH_A5_1 kc=61855fb81fc2a800 retrieve_imeisv=0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- needs ciph, not yet accepted
@@ -1502,7 +1529,8 @@ DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI_TMSI
-- DTAP --> MS: 051802
+DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: 051802
- DTAP matches expected message
DREF VLR subscr MSISDN:46071 usage decreases to: 1
<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
@@ -1532,6 +1560,7 @@ DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
+DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF MSISDN:46071: MSC conn use - 1 == 1
- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
llist_count(&net->subscr_conns) == 1
@@ -1568,20 +1597,21 @@ DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from paren
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 1
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 1
@@ -1604,14 +1634,13 @@ DMM Subscriber MSISDN:46071 DETACHED
DREF VLR subscr MSISDN:46071 usage decreases to: 1
DREF VLR subscr MSISDN:46071 usage decreases to: 0
DREF freeing VLR subscr MSISDN:46071
-DMM No conn_fsm, release conn
-DMM compl_l3: Discarding conn
+DREF unknown: MSC conn use - 1 == 0
DRLL Freeing subscriber connection with NULL subscriber
llist_count(&net->subscr_conns) == 0
===== test_ciph_tmsi_imei: SUCCESS
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
-talloc_total_blocks(tall_bsc_ctx) == 75
+talloc_total_blocks(tall_bsc_ctx) == 9
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 9