aboutsummaryrefslogtreecommitdiffstats
path: root/openbsc/tests/msc_vlr/msc_vlr_test_ms_timeout.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_ms_timeout.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_ms_timeout.err')
-rw-r--r--openbsc/tests/msc_vlr/msc_vlr_test_ms_timeout.err84
1 files changed, 44 insertions, 40 deletions
diff --git a/openbsc/tests/msc_vlr/msc_vlr_test_ms_timeout.err b/openbsc/tests/msc_vlr/msc_vlr_test_ms_timeout.err
index d0b54aea7..3250e293b 100644
--- a/openbsc/tests/msc_vlr/msc_vlr_test_ms_timeout.err
+++ b/openbsc/tests/msc_vlr/msc_vlr_test_ms_timeout.err
@@ -6,9 +6,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
@@ -28,7 +28,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
@@ -65,14 +65,15 @@ DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
llist_count(&net->subscr_conns) == 1
lu_result_sent == 0
- Total time passed: 5.001598 s
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Connection timed out
- sending LU Reject for IMSI:901700000004620, cause 22
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
-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_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_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: 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_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Removing from parent vlr_lu_fsm(901700000004620)
@@ -86,17 +87,17 @@ DREF IMSI:901700000004620: MSC conn use - 1 == 0
DRLL subscr IMSI:901700000004620: Freeing subscriber connection
DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
DREF freeing VLR subscr IMSI:901700000004620
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
llist_count(&net->subscr_conns) == 0
lu_result_sent == 2
===== test_ms_timeout_lu_auth_resp: 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_ms_timeout_cm_auth_resp
- Total time passed: 0.000000 s
@@ -106,9 +107,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
@@ -128,7 +129,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
@@ -171,6 +172,7 @@ DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HL
DVLR GSUP tx: 04010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
+DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
lu_result_sent == 0
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
@@ -218,12 +220,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
@@ -232,8 +235,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
@@ -247,9 +250,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 (no Ciph)
@@ -267,7 +270,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
cm_service_result_sent == 0
auth_request_sent == 1
@@ -290,16 +293,17 @@ DREF MSISDN:46071: MSC conn use - 1 == 1
llist_count(&net->subscr_conns) == 1
cm_service_result_sent == 0
- Total time passed: 5.001598 s
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Connection timed out
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_TIMEOUT)
DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: 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_TIMEOUT
- sending CM Service Reject for MSISDN:46071, result VLR_PR_ARQ_RES_TIMEOUT
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
-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_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_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 2
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: 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 VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Removing from parent Process_Access_Request_VLR(901700000004620)
@@ -311,10 +315,10 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_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: 1
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
-DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
llist_count(&net->subscr_conns) == 0
cm_service_result_sent == 2
@@ -322,7 +326,7 @@ DREF freeing VLR subscr MSISDN:46071
===== test_ms_timeout_cm_auth_resp: 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