diff options
| author | Neels Hofmeyr <neels@hofmeyr.de> | 2018-03-31 00:02:14 +0200 |
|---|---|---|
| committer | Harald Welte <laforge@gnumonks.org> | 2018-04-11 21:39:44 +0000 |
| commit | e3d3dc6ea218a07161eeb80ae864a96bef2d8e61 (patch) | |
| tree | b0d8bddeda0835e20b4d0592184a4ec2befe7d07 /tests/msc_vlr/msc_vlr_test_reject_concurrency.err | |
| parent | dc2514b22062af04354c0331f0f5819051c3fdee (diff) | |
refactor subscr_conn and subscr_conn_fsm de-/alloc
Refactor:
1. Glue the gsm_subscriber_connection alloc to the subscr_conn_fsm.
2. Add separate AUTH_CIPH state to the FSM.
3. Use conn->use_count to trigger conn release.
4. Add separate RELEASING state to the FSM.
5. Add rate counters for each of the three Complete Layer 3 types.
Details:
1. Glue the gsm_subscriber_connection alloc to the subscr_conn_fsm.
Historically, a gsm_subscriber_connection was allocated in libbsc land, and
only upon Complete Layer 3 did libmsc add the fsm instance. After splitting
openbsc.git into a separate osmo-msc, this is no longer necessary, hence:
Closely tie gsm_subscriber_connection allocation to the subscr_conn_fsm
instance: talloc the conn as a child of the FSM instance, and discard the conn
as soon as the FSM terminates.
2. Add separate AUTH_CIPH state to the FSM.
Decoding the Complete Layer 3 message is distinctly separate from waiting for
the VLR FSMs to conclude. Use the NEW state as "we don't know if this is a
valid message yet", and the AUTH_CIPH state as "evaluating, don't release".
A profound effect of this: should we for any odd reason fail to leave the FSM's
NEW state, the conn will be released right at the end of msc_compl_l3(),
without needing to trigger release in each code path.
3. Use conn->use_count to trigger conn release.
Before, the FSM itself would hold a use count on the conn, and hence we would
need to ask it whether it is ready to release the conn yet by dispatching
events, to achieve a use_count decrement.
Instead, unite the FSM instance and conn, and do not hold a use count by the
FSM. Hence, trigger an FSM "UNUSED" event only when the use_count reaches zero.
As long as use counts are done correctly, the FSM will terminate correctly.
These exceptions:
- The new AUTH_CIPH state explicitly ignores UNUSED events, since we expect the
use count to reach zero while evaluating Authentication and Ciphering. (I
experimented with holding a use count by AUTH_CIPH onenter() and releasing by
onleave(), but the use count and thus the conn are released before the next
state can initiate transactions that would increment the use count again.
Same thing for the VLR FSMs holding a use count, they should be done before
we advance to the next state. The easiest is to simply expect zero use count
during the AUTH_CIPH state.)
- A CM Service Request means that even though the MSC would be through with all
it wants to do, we shall still wait for a request to follow from the MS.
Hence the FSM holds a use count on itself while a CM Service is pending.
- While waiting for a Release/Clear Complete, the FSM holds a use count on
itself.
4. Add separate RELEASING state to the FSM.
If we decide to release for other reasons than a use count reaching zero, we
still need to be able to wait for the msc_dtap() use count on the conn to
release.
(An upcoming patch will further use the RELEASING state to properly wait for
Clear Complete / Release Complete messages.)
5. Add rate counters for each of the three Complete Layer 3 types.
Besides LU, also count CM Service Request and Paging Response
acceptance/rejections. Without these counters, only very few of the auth+ciph
outcomes actually show in the counters.
Related: OS#3122
Change-Id: I55feb379e176a96a831e105b86202b17a0ffe889
Diffstat (limited to 'tests/msc_vlr/msc_vlr_test_reject_concurrency.err')
| -rw-r--r-- | tests/msc_vlr/msc_vlr_test_reject_concurrency.err | 701 |
1 files changed, 355 insertions, 346 deletions
diff --git a/tests/msc_vlr/msc_vlr_test_reject_concurrency.err b/tests/msc_vlr/msc_vlr_test_reject_concurrency.err index bd7b47c52..7dca53f7b 100644 --- a/tests/msc_vlr/msc_vlr_test_reject_concurrency.err +++ b/tests/msc_vlr/msc_vlr_test_reject_concurrency.err @@ -5,12 +5,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request on one connection MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -34,19 +31,19 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - Another Location Update Request from the same subscriber on another connection is rejected MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -59,22 +56,24 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: A Location Updating process is - sending LU Reject for unknown, cause 22 DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_DONE DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DREF unknown: MSC conn use + release == 2 (0x101) +- BSSAP Clear --RAN_GERAN_A--> MS +DREF unknown: MSC conn use - release == 1 (0x1) +DREF VLR subscr IMSI:901700000004620 usage decreases to: 1 +DRR 901700000004620: internal error during Location Updating attempt +DREF unknown: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=unknown, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF unknown: MSC conn use - fsm == 1 (0x1) +DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated -DREF VLR subscr IMSI:901700000004620 usage decreases to: 1 -DRR 901700000004620: internal error during Location Updating attempt -DREF unknown: MSC conn use - compl_l3 == 0 (0x0) -DRLL Freeing subscriber connection with NULL subscriber bssap_clear_sent == 1 lu_result_sent == 2 llist_count(&net->subscr_conns) == 1 @@ -126,21 +125,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -160,12 +162,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -189,18 +188,22 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 --- - Another Location Update Request from the same subscriber on the same conn is dropped silently MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST -DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6) +DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DMM 901700000004620: Error: connection already in use -DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4) +DMM Cannot accept another LU, conn already busy establishing authenticity; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH +DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 --- @@ -251,21 +254,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -285,12 +291,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -314,23 +317,27 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 --- - A CM Service Request in the middle of a LU is rejected MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ -DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6) +DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2) DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620 -DMM IMSI:901700000004620: connection already in use +DMM Cannot accept CM Service Request, conn already busy establishing authenticity DMM -> CM SERVICE Reject cause: 17 DMSC msc_tx 3 bytes to IMSI:901700000004620 via RAN_GERAN_A - DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_CM_SERV_REJ: 052211 - DTAP matches expected message -DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4) +DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 cm_service_result_sent == 0 dtap_tx_confirmed == 1 @@ -383,21 +390,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -417,12 +427,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -446,19 +453,22 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 --- - An erratic Paging Response is dropped silently MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP -DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6) +DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2) DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) -DRR PAGING RESPONSE: MI(IMSI)=901700000004620 -DMM 901700000004620: Error: connection already in use -DMM IMSI:901700000004620: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4) +DMM Ignoring Paging Response, conn already busy establishing authenticity +DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 --- @@ -509,21 +519,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -545,12 +558,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -574,8 +584,11 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -624,21 +637,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -652,13 +668,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 1 - Subscriber does a normal CM Service Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620 -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ 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) @@ -678,30 +691,27 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED - sending CM Service Accept for MSISDN:46071 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9) 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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request DREF VLR subscr MSISDN:46071 usage decreases to: 2 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted +DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8) cm_service_result_sent == 1 msc_subscr_conn_is_accepted() == true - A LU request on an open conn is dropped silently MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DMM 901700000004620: Error: connection already in use -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4) +DMM Cannot accept another LU, conn already established; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8) lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 --- - subscriber detaches MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1) DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620 DREF VLR subscr MSISDN:46071 usage increases to: 3 @@ -711,20 +721,25 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from p DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE -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) -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 3 (0x10a) +DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 - BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2) -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 - release == 1 (0x2) DREF VLR subscr MSISDN:46071 usage decreases to: 2 DREF VLR subscr MSISDN:46071 usage decreases to: 1 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore. +DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already in release, ignore. DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 0 DREF freeing VLR subscr MSISDN:46071 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated bssap_clear_sent == 1 llist_count(&net->subscr_conns) == 0 ===== test_reject_lu_during_cm: SUCCESS @@ -738,12 +753,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -767,8 +779,11 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -817,21 +832,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -845,13 +863,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 1 - Subscriber does a normal CM Service Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620 -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ 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) @@ -871,33 +886,30 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED - sending CM Service Accept for MSISDN:46071 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9) 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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request DREF VLR subscr MSISDN:46071 usage decreases to: 2 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted +DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8) cm_service_result_sent == 1 msc_subscr_conn_is_accepted() == true - A second CM Service Request on the same conn is accepted without another auth dance MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620 DMM MSISDN:46071: re-using already accepted connection DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID from CM_SERVICE_REQ - sending CM Service Accept for MSISDN:46071 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4) +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8) cm_service_result_sent == 1 llist_count(&net->subscr_conns) == 1 --- - subscriber detaches MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1) DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620 DREF VLR subscr MSISDN:46071 usage increases to: 3 @@ -907,20 +919,25 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from p DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_CN_CLOSE -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) -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 3 (0x10a) +DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 - BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2) -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 - release == 1 (0x2) DREF VLR subscr MSISDN:46071 usage decreases to: 2 DREF VLR subscr MSISDN:46071 usage decreases to: 1 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore. +DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already in release, ignore. DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 0 DREF freeing VLR subscr MSISDN:46071 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated bssap_clear_sent == 1 llist_count(&net->subscr_conns) == 0 ===== test_reject_cm_during_cm: SUCCESS @@ -934,12 +951,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -963,8 +977,11 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -1013,21 +1030,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -1041,13 +1061,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 1 - Subscriber does a normal CM Service Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620 -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ 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) @@ -1067,26 +1084,22 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED - sending CM Service Accept for MSISDN:46071 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DREF MSISDN:46071: MSC conn use + cm_service == 2 (0x9) 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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request DREF VLR subscr MSISDN:46071 usage decreases to: 2 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted +DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x8) cm_service_result_sent == 1 msc_subscr_conn_is_accepted() == true --- - An erratic Paging Response on the same conn is dropped silently MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) -DRR PAGING RESPONSE: MI(IMSI)=901700000004620 -DMM 901700000004620: Error: connection already in use -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4) +DMM Ignoring Paging Response, conn already established +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8) llist_count(&net->subscr_conns) == 1 --- - The original CM Service Request can conclude @@ -1094,9 +1107,10 @@ DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4) expecting USSD: Your extension is 46071
MSC <--RAN_GERAN_A-- MS: NCSS:0x3b -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b) DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false +DREF MSISDN:46071: MSC conn use - cm_service == 1 (0x2) 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 @@ -1104,22 +1118,25 @@ DMM MSISDN:46071: MSISDN = 46071 DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A - DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d - DTAP matches expected message -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED +DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 3 +DREF VLR subscr MSISDN:46071 usage decreases to: 2 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2) +DRLL MSISDN:46071: Freeing subscriber connection +DREF VLR subscr MSISDN:46071 usage decreases to: 1 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 - dtap == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection -DREF VLR subscr MSISDN:46071 usage decreases to: 1 bssap_clear_sent == 1 - all requests serviced, conn has been released llist_count(&net->subscr_conns) == 0 @@ -1135,12 +1152,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -1164,8 +1178,11 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -1214,21 +1231,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -1254,13 +1274,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 3 - MS replies with Paging Response, we deliver the SMS MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) DRR PAGING RESPONSE: MI(IMSI)=901700000004620 -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP 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) @@ -1279,22 +1296,21 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_do DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: 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 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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. DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction DREF VLR subscr MSISDN:46071 usage increases to: 6 -DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x15) +DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21) DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05 - DTAP matches expected message DREF VLR subscr MSISDN:46071 usage decreases to: 5 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS DREF VLR subscr MSISDN:46071 usage decreases to: 4 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted +DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20) dtap_tx_confirmed == 1 paging_stopped == 1 - conn is still open to wait for SMS ack dance @@ -1302,27 +1318,23 @@ DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14) --- - MS sends erratic LU Request, which is dropped silently MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DMM 901700000004620: Error: connection already in use -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14) +DMM Cannot accept another LU, conn already established; extraneous LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20) lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - MS replies with CP-ACK for received SMS MSC <--RAN_GERAN_A-- MS: SMS:0x04 -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4) 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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14) +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20) llist_count(&net->subscr_conns) == 1 - MS also sends RP-ACK, MSC in turn sends CP-ACK for that MSC <--RAN_GERAN_A-- MS: SMS:0x01 -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1) 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 @@ -1330,23 +1342,26 @@ DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A - 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 - trans_sms == 2 (0x6) -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED +DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2) +DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 3 +DREF VLR subscr MSISDN:46071 usage decreases to: 2 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2) +DRLL MSISDN:46071: Freeing subscriber connection +DREF VLR subscr MSISDN:46071 usage decreases to: 1 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 - dtap == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection -DREF VLR subscr MSISDN:46071 usage decreases to: 1 dtap_tx_confirmed == 1 bssap_clear_sent == 1 - SMS is done @@ -1363,12 +1378,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -1392,8 +1404,11 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -1442,21 +1457,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -1482,13 +1500,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 3 - MS replies with Paging Response, we deliver the SMS MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) DRR PAGING RESPONSE: MI(IMSI)=901700000004620 -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP 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) @@ -1507,22 +1522,21 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_do DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: 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 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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. DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction DREF VLR subscr MSISDN:46071 usage increases to: 6 -DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x15) +DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21) DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05 - DTAP matches expected message DREF VLR subscr MSISDN:46071 usage decreases to: 5 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS DREF VLR subscr MSISDN:46071 usage decreases to: 4 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted +DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20) dtap_tx_confirmed == 1 paging_stopped == 1 - conn is still open to wait for SMS ack dance @@ -1530,31 +1544,28 @@ DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14) --- - CM Service Request during open connection is accepted MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620 DMM MSISDN:46071: re-using already accepted connection +DREF MSISDN:46071: MSC conn use + cm_service == 3 (0x2a) DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Updated ID from PAGING_RESP - sending CM Service Accept for MSISDN:46071 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14) +DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28) cm_service_result_sent == 1 llist_count(&net->subscr_conns) == 1 g_conn->received_cm_service_request == 1 - MS replies with CP-ACK for received SMS MSC <--RAN_GERAN_A-- MS: SMS:0x04 -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a) DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4) 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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14) +DREF MSISDN:46071: MSC conn use - dtap == 2 (0x28) llist_count(&net->subscr_conns) == 1 - MS also sends RP-ACK, MSC in turn sends CP-ACK for that MSC <--RAN_GERAN_A-- MS: SMS:0x01 -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 3 (0x2a) DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1) 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 @@ -1562,19 +1573,15 @@ DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A - 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 - trans_sms == 2 (0x6) -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request -DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4) +DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0xa) +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x8) dtap_tx_confirmed == 1 - SMS is done llist_count(&net->subscr_conns) == 1 --- - subscriber detaches MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND -DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0xa) DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1) DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620 DREF VLR subscr MSISDN:46071 usage increases to: 3 @@ -1584,20 +1591,25 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from p DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE -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) -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 3 (0x10a) +DREF MSISDN:46071: MSC conn use - cm_service == 2 (0x102) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 - BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2) -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 - release == 1 (0x2) DREF VLR subscr MSISDN:46071 usage decreases to: 2 DREF VLR subscr MSISDN:46071 usage decreases to: 1 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore. +DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already in release, ignore. DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 0 DREF freeing VLR subscr MSISDN:46071 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated bssap_clear_sent == 1 llist_count(&net->subscr_conns) == 0 ===== test_accept_cm_during_paging_resp: SUCCESS @@ -1611,12 +1623,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12 - Location Update Request MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from LU DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH DMM LU/new-LAC: 1/23 @@ -1640,8 +1649,11 @@ 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: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW) -DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED lu_result_sent == 0 llist_count(&net->subscr_conns) == 1 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -1690,21 +1702,24 @@ 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 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 4 +DREF VLR subscr MSISDN:46071 usage decreases to: 3 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection +DRLL MSISDN:46071: Freeing subscriber connection DREF VLR subscr MSISDN:46071 usage decreases to: 2 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated @@ -1730,13 +1745,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 3 - MS replies with Paging Response, we deliver the SMS MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated DREF unknown: MSC conn use + compl_l3 == 1 (0x1) DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) DRR PAGING RESPONSE: MI(IMSI)=901700000004620 -DREF unknown: MSC conn use + fsm == 2 (0x5) -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 Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP 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) @@ -1755,22 +1767,21 @@ DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_do DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: 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 DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED -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. DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction DREF VLR subscr MSISDN:46071 usage increases to: 6 -DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x15) +DREF MSISDN:46071: MSC conn use + trans_sms == 2 (0x21) DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A - DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05 - DTAP matches expected message DREF VLR subscr MSISDN:46071 usage decreases to: 5 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: SMS DREF VLR subscr MSISDN:46071 usage decreases to: 4 -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Event SUBSCR_CONN_E_COMPLETE_LAYER_3 not permitted +DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x20) dtap_tx_confirmed == 1 paging_stopped == 1 - conn is still open to wait for SMS ack dance @@ -1778,26 +1789,21 @@ DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14) --- - MS sends another erratic Paging Response which is dropped silently MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) -DRR PAGING RESPONSE: MI(IMSI)=901700000004620 -DMM 901700000004620: Error: connection already in use -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14) +DMM Ignoring Paging Response, conn already established +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20) - MS replies with CP-ACK for received SMS MSC <--RAN_GERAN_A-- MS: SMS:0x04 -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4) 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_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS -DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14) +DREF MSISDN:46071: MSC conn use - dtap == 1 (0x20) llist_count(&net->subscr_conns) == 1 - MS also sends RP-ACK, MSC in turn sends CP-ACK for that MSC <--RAN_GERAN_A-- MS: SMS:0x01 -DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16) +DREF MSISDN:46071: MSC conn use + dtap == 2 (0x22) DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1) 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 @@ -1805,23 +1811,26 @@ DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A - 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 - trans_sms == 2 (0x6) -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn -DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED +DREF MSISDN:46071: MSC conn use - trans_sms == 1 (0x2) +DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DREF MSISDN:46071: MSC conn use + release == 1 (0x100) +DREF VLR subscr MSISDN:46071 usage increases to: 3 +DREF VLR subscr MSISDN:46071 usage decreases to: 2 +- BSSAP Clear --RAN_GERAN_A--> MS +DREF MSISDN:46071: MSC conn use - release == 0 (0x0) +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: 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 -DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event. -- BSSAP Clear --RAN_GERAN_A--> MS -DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2) +DRLL MSISDN:46071: Freeing subscriber connection +DREF VLR subscr MSISDN:46071 usage decreases to: 1 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 - dtap == 0 (0x0) -DRLL subscr MSISDN:46071: Freeing subscriber connection -DREF VLR subscr MSISDN:46071 usage decreases to: 1 dtap_tx_confirmed == 1 bssap_clear_sent == 1 - SMS is done |