properly receive BSSMAP Clear Complete and Iu Release Complete

When sending a BSSMAP Clear or Iu Release, do not immediately discard the conn,
but wait until a BSSMAP Clear Complete / Iu Release Complete has been received.

Hence we will no longer show in the log that an incoming Release/Clear Complete
belongs to an unknown subscriber, but will still be around to properly log the
release.

Related: OS#3122
Change-Id: Ie4c6aaba3866d6e5b98004e8870a215e8cf8ffc1

4 files changed, 83 insertions, 15 deletions

diff --git a/src/libmsc/a_iface_bssap.c b/src/libmsc/a_iface_bssap.c
index d0d6bc03e..87ccf0532 100644
--- a/src/libmsc/a_iface_bssap.c
+++ b/src/libmsc/a_iface_bssap.c
@@ -239,11 +239,16 @@ static int bssmap_rx_clear_rqst(struct gsm_subscriber_connection *conn,
 
 /* Endpoint to handle BSSMAP clear complete */
 static int bssmap_rx_clear_complete(struct osmo_sccp_user *scu,
-				    const struct a_conn_info *a_conn_info, struct msgb *msg)
+				    const struct a_conn_info *a_conn_info,
+				    struct gsm_subscriber_connection *conn)
 {
 	int rc;
 
-	LOGP(DMSC, LOGL_INFO, "Rx BSSMAP CLEAR COMPLETE, releasing SCCP connection\n");
+	LOGPCONN(conn, LOGL_INFO, "Rx BSSMAP CLEAR COMPLETE, releasing SCCP connection\n");
+
+	if (conn)
+		msc_subscr_conn_rx_bssmap_clear_complete(conn);
+
 	rc = osmo_sccp_tx_disconn(scu, a_conn_info->conn_id,
 				  NULL, SCCP_RELEASE_CAUSE_END_USER_ORIGINATED);
 
@@ -568,8 +573,6 @@ static int rx_bssmap(struct osmo_sccp_user *scu, const struct a_conn_info *a_con
 	switch (msg_type) {
 	case BSS_MAP_MSG_COMPLETE_LAYER_3:
 		return bssmap_rx_l3_compl(scu, a_conn_info, msg, &tp);
-	case BSS_MAP_MSG_CLEAR_COMPLETE:
-		return bssmap_rx_clear_complete(scu, a_conn_info, msg);
 	default:
 		break;
 	}
@@ -577,6 +580,13 @@ static int rx_bssmap(struct osmo_sccp_user *scu, const struct a_conn_info *a_con
 	conn = subscr_conn_lookup_a(a_conn_info->network, a_conn_info->conn_id);
 	if (!conn) {
 		LOGP(DBSSAP, LOGL_ERROR, "Couldn't find subscr_conn for conn_id=%d\n", a_conn_info->conn_id);
+		/* We expect a Clear Complete to come in on a valid conn. But if for some reason we still
+		 * have the SCCP connection while the subscriber connection data is already gone, at
+		 * least close the SCCP conn. */
+
+		if (msg_type == BSS_MAP_MSG_CLEAR_COMPLETE)
+			return bssmap_rx_clear_complete(scu, a_conn_info, NULL);
+
 		return -EINVAL;
 	}
 
@@ -585,6 +595,8 @@ static int rx_bssmap(struct osmo_sccp_user *scu, const struct a_conn_info *a_con
 	switch (msg_type) {
 	case BSS_MAP_MSG_CLEAR_RQST:
 		return bssmap_rx_clear_rqst(conn, msg, &tp);
+	case BSS_MAP_MSG_CLEAR_COMPLETE:
+		return bssmap_rx_clear_complete(scu, a_conn_info, conn);
 	case BSS_MAP_MSG_CLASSMARK_UPDATE:
 		return bssmap_rx_classmark_upd(conn, msg, &tp);
 	case BSS_MAP_MSG_CIPHER_MODE_COMPLETE:
diff --git a/src/libmsc/iucs_ranap.c b/src/libmsc/iucs_ranap.c
index 57cd50eed..ec0b569c7 100644
--- a/src/libmsc/iucs_ranap.c
+++ b/src/libmsc/iucs_ranap.c
@@ -117,7 +117,7 @@ int iucs_rx_ranap_event(struct gsm_network *network,
 	case RANAP_IU_EVENT_LINK_INVALIDATED:
 		LOGP(DIUCS, LOGL_INFO, "IuCS release for %s\n",
 		     vlr_subscr_name(conn->vsub));
-		msc_subscr_conn_close(conn, 0);
+		msc_subscr_conn_rx_iu_release_complete(conn);
 		return 0;
 
 	case RANAP_IU_EVENT_SECURITY_MODE_COMPLETE:
diff --git a/src/libmsc/osmo_msc.c b/src/libmsc/osmo_msc.c
index a5184b213..cc67a5ac9 100644
--- a/src/libmsc/osmo_msc.c
+++ b/src/libmsc/osmo_msc.c
@@ -283,6 +283,11 @@ void _msc_subscr_conn_put(struct gsm_subscriber_connection *conn,
 		osmo_fsm_inst_dispatch(conn->fi, SUBSCR_CONN_E_UNUSED, NULL);
 }
 
+bool msc_subscr_conn_used_by(struct gsm_subscriber_connection *conn, enum msc_subscr_conn_use token)
+{
+	return conn && (conn->use_tokens & (1 << token));
+}
+
 const struct value_string msc_subscr_conn_use_names[] = {
 	{MSC_CONN_USE_UNTRACKED,	"UNTRACKED"},
 	{MSC_CONN_USE_COMPL_L3,		"compl_l3"},
diff --git a/src/libmsc/subscr_conn.c b/src/libmsc/subscr_conn.c
index e3a6b248c..1ca6b2d41 100644
--- a/src/libmsc/subscr_conn.c
+++ b/src/libmsc/subscr_conn.c
@@ -260,8 +260,11 @@ static void subscr_conn_fsm_releasing_onenter(struct osmo_fsm_inst *fi, uint32_t
 {
 	struct gsm_subscriber_connection *conn = fi->priv;
 
-	/* While we're still checking on release, prevent a last use count decrement from deallocating */
-	msc_subscr_conn_get(conn, MSC_CONN_USE_RELEASE);
+	/* Use count for either conn->a.waiting_for_clear_complete or
+	 * conn->iu.waiting_for_release_complete. 'get' it early, so we don't deallocate after tearing
+	 * down active transactions. Safeguard against double-get (though it shouldn't happen). */
+	if (!msc_subscr_conn_used_by(conn, MSC_CONN_USE_RELEASE))
+		msc_subscr_conn_get(conn, MSC_CONN_USE_RELEASE);
 
 	/* Cancel pending CM Service Requests */
 	if (conn->received_cm_service_request) {
@@ -278,20 +281,27 @@ static void subscr_conn_fsm_releasing_onenter(struct osmo_fsm_inst *fi, uint32_t
 	switch (conn->via_ran) {
 	case RAN_GERAN_A:
 		a_iface_tx_clear_cmd(conn);
+		if (conn->a.waiting_for_clear_complete) {
+			LOGPFSML(fi, LOGL_ERROR,
+				 "Unexpected: conn is already waiting for BSSMAP Clear Complete\n");
+			break;
+		}
+		conn->a.waiting_for_clear_complete = true;
 		break;
 	case RAN_UTRAN_IU:
 		ranap_iu_tx_release(conn->iu.ue_ctx, NULL);
+		if (conn->iu.waiting_for_release_complete) {
+			LOGPFSML(fi, LOGL_ERROR,
+				 "Unexpected: conn is already waiting for Iu Release Complete\n");
+			break;
+		}
+		conn->iu.waiting_for_release_complete = true;
 		break;
 	default:
 		LOGP(DMM, LOGL_ERROR, "%s: Unknown RAN type, cannot tx release/clear\n",
 		     vlr_subscr_name(conn->vsub));
 		break;
 	}
-
-	/* FIXME: keep the conn until the Iu Release Outcome is
-	 * received from the UE, or a timeout expires. For now, the log
-	 * says "unknown UE" for each release outcome. */
-	msc_subscr_conn_put(conn, MSC_CONN_USE_RELEASE);
 }
 
 static void subscr_conn_fsm_releasing(struct osmo_fsm_inst *fi, uint32_t event, void *data)
@@ -456,7 +466,7 @@ void subscr_conn_release_when_unused(struct gsm_subscriber_connection *conn)
 	osmo_fsm_inst_dispatch(conn->fi, SUBSCR_CONN_E_RELEASE_WHEN_UNUSED, NULL);
 }
 
-void msc_subscr_conn_close(struct gsm_subscriber_connection *conn, uint32_t cause)
+static void conn_close(struct gsm_subscriber_connection *conn, uint32_t cause, uint32_t event)
 {
 	if (!conn) {
 		LOGP(DMM, LOGL_ERROR, "Cannot release NULL connection\n");
@@ -467,11 +477,23 @@ void msc_subscr_conn_close(struct gsm_subscriber_connection *conn, uint32_t caus
 		       __func__, vlr_subscr_name(conn->vsub), cause);
 		return;
 	}
-	osmo_fsm_inst_dispatch(conn->fi, SUBSCR_CONN_E_CN_CLOSE, &cause);
+	osmo_fsm_inst_dispatch(conn->fi, event, &cause);
+}
+
+void msc_subscr_conn_close(struct gsm_subscriber_connection *conn, uint32_t cause)
+{
+	return conn_close(conn, cause, SUBSCR_CONN_E_CN_CLOSE);
+}
+
+void msc_subscr_conn_mo_close(struct gsm_subscriber_connection *conn, uint32_t cause)
+{
+	return conn_close(conn, cause, SUBSCR_CONN_E_MO_CLOSE);
 }
 
 bool msc_subscr_conn_in_release(struct gsm_subscriber_connection *conn)
 {
+	if (!conn || !conn->fi)
+		return true;
 	if (conn->fi->state == SUBSCR_CONN_S_RELEASING)
 		return true;
 	if (conn->fi->state == SUBSCR_CONN_S_RELEASED)
@@ -491,7 +513,8 @@ bool msc_subscr_conn_is_accepted(const struct gsm_subscriber_connection *conn)
 	return true;
 }
 
-/* Indicate that *some* communication is happening with the phone. */
+/* Indicate that *some* communication is happening with the phone, so that the conn FSM no longer times
+ * out to release within a few seconds. */
 void msc_subscr_conn_communicating(struct gsm_subscriber_connection *conn)
 {
 	osmo_fsm_inst_dispatch(conn->fi, SUBSCR_CONN_E_COMMUNICATING, NULL);
@@ -544,6 +567,7 @@ bool msc_subscr_conn_is_establishing_auth_ciph(const struct gsm_subscriber_conne
 	return conn->fi->state == SUBSCR_CONN_S_AUTH_CIPH;
 }
 
+
 const struct value_string complete_layer3_type_names[] = {
 	{ COMPLETE_LAYER3_NONE, "NONE" },
 	{ COMPLETE_LAYER3_LU, "LU" },
@@ -559,3 +583,30 @@ void msc_subscr_conn_update_id(struct gsm_subscriber_connection *conn,
        osmo_fsm_inst_update_id(conn->fi, id);
        LOGPFSML(conn->fi, LOGL_DEBUG, "Updated ID from %s\n", complete_layer3_type_name(from));
 }
+
+static void rx_close_complete(struct gsm_subscriber_connection *conn, const char *label, bool *flag)
+{
+	if (!conn)
+		return;
+	if (!msc_subscr_conn_in_release(conn)) {
+		LOGPFSML(conn->fi, LOGL_ERROR, "Received unexpected %s, discarding right now\n",
+			 label);
+		trans_conn_closed(conn);
+		osmo_fsm_inst_term(conn->fi, OSMO_FSM_TERM_ERROR, NULL);
+		return;
+	}
+	if (*flag) {
+		*flag = false;
+		msc_subscr_conn_put(conn, MSC_CONN_USE_RELEASE);
+	}
+}
+
+void msc_subscr_conn_rx_bssmap_clear_complete(struct gsm_subscriber_connection *conn)
+{
+	rx_close_complete(conn, "BSSMAP Clear Complete", &conn->a.waiting_for_clear_complete);
+}
+
+void msc_subscr_conn_rx_iu_release_complete(struct gsm_subscriber_connection *conn)
+{
+	rx_close_complete(conn, "Iu Release Complete", &conn->iu.waiting_for_release_complete);
+}