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

1 files changed, 92 insertions, 65 deletions

diff --git a/tests/msc_vlr/msc_vlr_test_ms_timeout.err b/tests/msc_vlr/msc_vlr_test_ms_timeout.err
index fc4e4896e..a3950edc2 100644
--- a/tests/msc_vlr/msc_vlr_test_ms_timeout.err
+++ b/tests/msc_vlr/msc_vlr_test_ms_timeout.err
@@ -6,12 +6,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12
 - Location Update request causes a GSUP Send Auth Info request to HLR
   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
@@ -32,8 +29,11 @@ DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VL
 DVLR GSUP tx: 08010809710000004026f0
 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
 DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
-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
 - from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
 <-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
@@ -69,13 +69,22 @@ DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
   llist_count(&net->subscr_conns) == 1
   lu_result_sent == 0
 - Total time passed: 5.001598 s
-DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Timeout of T0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Close event, cause 38
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF IMSI:901700000004620: MSC conn use + release == 1 (0x100)
 DREF VLR subscr IMSI:901700000004620 usage increases to: 2
 DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Connection timed out
 - sending LU Reject for IMSI:901700000004620, cause 22
 DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
-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_RELEASING}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
+DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF IMSI:901700000004620: 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_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
@@ -86,15 +95,11 @@ DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Co
 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=IMSI:901700000004620, cause=2): no conn fsm, releasing directly without release event.
-- BSSAP Clear --RAN_GERAN_A--> MS
-DREF IMSI:901700000004620: MSC conn use - fsm == 0 (0x0)
-DRLL subscr IMSI:901700000004620: Freeing subscriber connection
-DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
-DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
-DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+DRLL IMSI:901700000004620: Freeing subscriber connection
 DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
 DREF freeing VLR subscr IMSI:901700000004620
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
 - SUBSCR_CONN_TIMEOUT has passed, conn is gone.
   bssap_clear_sent == 1
   llist_count(&net->subscr_conns) == 0
@@ -109,12 +114,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12
 - Location Update request causes a GSUP Send Auth Info request to HLR
   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
@@ -135,8 +137,11 @@ DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VL
 DVLR GSUP tx: 08010809710000004026f0
 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
 DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
-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
 - from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
 <-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
@@ -155,7 +160,7 @@ DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
   lu_result_sent == 0
 - MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_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_MM_AUTH_RESP (0x5:0x14)
 DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
 DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
@@ -178,8 +183,9 @@ 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 - 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
 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
 <-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
@@ -227,21 +233,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
@@ -255,13 +264,10 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 1
 - after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
   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)
@@ -280,8 +286,11 @@ DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: us
 - ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
 - ...expecting sres=20bde240
 DREF VLR subscr MSISDN:46071 usage decreases to: 2
-DMM MSISDN:46071: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
-DREF MSISDN:46071: 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 MSISDN:46071: 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
   cm_service_result_sent == 0
   auth_request_sent == 1
 ---
@@ -303,15 +312,24 @@ DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
   llist_count(&net->subscr_conns) == 1
   cm_service_result_sent == 0
 - Total time passed: 5.001598 s
-DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Timeout of T0
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Close event, cause 38
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: 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
 DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Connection timed out
 DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_TIMEOUT)
 DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
 DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_TIMEOUT
 - sending CM Service Reject for MSISDN:46071, result VLR_PR_ARQ_RES_TIMEOUT
-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_RELEASING}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASING}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
+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 VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
@@ -321,14 +339,10 @@ DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Deallocated
 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 == 0 (0x0)
-DRLL subscr MSISDN:46071: Freeing subscriber connection
-DREF VLR subscr MSISDN:46071 usage decreases to: 2
+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 VLR subscr MSISDN:46071 usage decreases to: 1
 - SUBSCR_CONN_TIMEOUT has passed, conn is gone.
   bssap_clear_sent == 1
   llist_count(&net->subscr_conns) == 0
@@ -344,12 +358,9 @@ talloc_total_blocks(tall_bsc_ctx) == 12
 - Location Update request causes a GSUP LU request to HLR
   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
@@ -373,8 +384,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
 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
 <-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
@@ -422,21 +436,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
@@ -498,6 +515,7 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 3
 - subscriber detaches, pagings are canceled
   MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
   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_IMSI_DETACH_IND (0x5:0x1)
 DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
@@ -510,10 +528,19 @@ DREF VLR subscr MSISDN:46071 usage decreases to: 2
 DREF VLR subscr MSISDN:46071 usage decreases to: 1
 DREF VLR subscr MSISDN:46071 usage decreases to: 0
 DREF freeing VLR subscr MSISDN:46071
-DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Close event, cause 0
+DMM Subscr_Conn{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 unknown: MSC conn use - compl_l3 == 0 (0x0)
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
 DRLL Freeing subscriber connection with NULL subscriber
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
   bssap_clear_sent == 1
   paging_stopped == 1
   llist_count(&net->subscr_conns) == 0