trans_free: tear down conn when last transaction is done

In trans_free(), call subscr_conn_release_when_unused(), so that we are sure to
clean up after the last transaction is done.

This fixes an error where a conn lingered after a CC failure, because that code
path forgot to trigger cleanup.

Rationale: so far we were triggering the release check after each DTAP dispatch
(compl_l3 and "normal" DTAP), which is sufficient for properly closed
transactions. We also need a check for when a timeout clears an erratic trans.

Adjust test expectation of test_call_mo_to_unknown_timeout to show that the
error is now fixed.

msc_vlr_test_reject_concurrency now sees an additional release checking event
when the SMS transaction is done, which is expected and does not affect the
test otherwise.

Related: OS#2779
Change-Id: I46ff2e9b09b67e4e0d79cccf8c04936f17281fcb

include/osmocom/msc/osmo_msc.h

@@ -110,4 +110,6 @@ void _msc_subscr_conn_put(struct gsm_subscriber_connection *conn,
 
 void msc_stop_paging(struct vlr_subscr *vsub);
 
+void subscr_conn_release_when_unused(struct gsm_subscriber_connection *conn);
+
 #endif

src/libmsc/osmo_msc.c

@@ -47,7 +47,7 @@ void msc_sapi_n_reject(struct gsm_subscriber_connection *conn, int dlci)
 		gsm411_sapi_n_reject(conn);
 }
 
-static void subscr_conn_release_when_unused(struct gsm_subscriber_connection *conn)
+void subscr_conn_release_when_unused(struct gsm_subscriber_connection *conn)
 {
 	if (!conn)
 		return;

src/libmsc/subscr_conn.c

@@ -371,8 +371,11 @@ bool msc_subscr_conn_is_accepted(const struct gsm_subscriber_connection *conn)
 void msc_subscr_conn_communicating(struct gsm_subscriber_connection *conn)
 {
 	OSMO_ASSERT(conn);
-	osmo_fsm_inst_dispatch(conn->conn_fsm, SUBSCR_CONN_E_COMMUNICATING,
+	/* This function is called to indicate that *some* communication is happening with the phone.
-			       NULL);
+	 * Late in the process, that may be a Release Confirm and the FSM and conn are already in
+	 * teardown. No need to signal SUBSCR_CONN_E_COMMUNICATING then. */
+	if (conn->conn_fsm)
+		osmo_fsm_inst_dispatch(conn->conn_fsm, SUBSCR_CONN_E_COMMUNICATING, NULL);
 }
 
 void msc_subscr_conn_init(void)

src/libmsc/transaction.c

@@ -117,6 +117,7 @@ struct gsm_trans *trans_alloc(struct gsm_network *net,
 void trans_free(struct gsm_trans *trans)
 {
 	enum msc_subscr_conn_use conn_usage_token = MSC_CONN_USE_UNTRACKED;
+	struct gsm_subscriber_connection *conn;
 
 	switch (trans->protocol) {
 	case GSM48_PDISC_CC:
@@ -153,8 +154,15 @@ void trans_free(struct gsm_trans *trans)
 	if (trans->conn)
 		msc_subscr_conn_put(trans->conn, conn_usage_token);
 
+	conn = trans->conn;
 	trans->conn = NULL;
 	talloc_free(trans);
+
+	/* trans_free() should always happen while the conn_fsm is still around. */
+	OSMO_ASSERT(conn->conn_fsm);
+
+	/* Possibly this was the last transaction used by this conn. */
+	subscr_conn_release_when_unused(conn);
 }
 
 /*! allocate an unused transaction ID for the given subscriber

tests/msc_vlr/msc_vlr_test_call.c

@@ -482,20 +482,13 @@ static void test_call_mo_to_unknown_timeout()
 	fake_time_passes(10, 23);
 
 	btw("The CC Release times out and we still properly clear the conn");
-	btw("ERROR: currently this is broken and will be fixed in a subsequent commit");
 	cc_to_mncc_expect_tx("", MNCC_REL_CNF);
-	expect_iu_release(); /* <-- will currently not work out */
+	expect_iu_release();
 	fake_time_passes(10, 23);
 	OSMO_ASSERT(cc_to_mncc_tx_confirmed);
-	/* EXPECTING ERROR: here, we should be able to do:
 	OSMO_ASSERT(iu_release_sent);
-	EXPECT_CONN_COUNT(0);
-	*/
-	BTW("This test is currently expecting erratic behavior:");
-	EXPECT_CONN_COUNT(1);
-	/* need to free manually for the sake of this test suite */
-	msc_subscr_conn_close(g_conn, 0);
 
+	EXPECT_CONN_COUNT(0);
 	clear_vlr();
 	comment_end();
 }

tests/msc_vlr/msc_vlr_test_call.err

@@ -349,7 +349,6 @@ DCC Sending 'MNCC_REL_CNF' to MNCC.
 DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
 DREF VLR subscr MSISDN:42342 usage decreases to: 2
 DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
-DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
@@ -732,7 +731,6 @@ DCC Sending 'MNCC_REL_CNF' to MNCC.
 DCC (ti 00 sub MSISDN:42342) new state RELEASE_REQ -> NULL
 DREF VLR subscr MSISDN:42342 usage decreases to: 2
 DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
-DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
@@ -1069,7 +1067,6 @@ DCC Sending 'MNCC_REL_CNF' to MNCC.
 DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
 DREF VLR subscr MSISDN:42342 usage decreases to: 2
 DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
-DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
@@ -1397,7 +1394,6 @@ DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
 - DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
 - DTAP matches expected message
 - The CC Release times out and we still properly clear the conn
-- ERROR: currently this is broken and will be fixed in a subsequent commit
 - Total time passed: 20.000046 s
   MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x80000003
 DMNCC transmit message MNCC_REL_CNF
@@ -1406,10 +1402,8 @@ DCC Sending 'MNCC_REL_CNF' to MNCC.
 DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
 DREF VLR subscr MSISDN:42342 usage decreases to: 2
 DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x4)
----
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
-- This test is currently expecting erratic behavior:
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
-  llist_count(&net->subscr_conns) == 1
-DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
 DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
@@ -1423,6 +1417,7 @@ DRLL subscr MSISDN:42342: Freeing subscriber connection
 DREF VLR subscr MSISDN:42342 usage decreases to: 1
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
 DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
+  llist_count(&net->subscr_conns) == 0
 DREF freeing VLR subscr MSISDN:42342
 ===== test_call_mo_to_unknown_timeout: SUCCESS
 

tests/msc_vlr/msc_vlr_test_reject_concurrency.err

@@ -1560,6 +1560,8 @@ 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)
   dtap_tx_confirmed == 1
 - SMS is done