subscr_conn: introduce usage tokens for ref error tracking

When hunting a conn use count bug, it was very hard to figure out who's (not)
using the conn. To ease tracking down this bug and future bugs, explicitly name
what a conn is being reserved for, and track in a bit mask.

Show in the DREF logs what uses and un-uses a conn. See the test expectation
updates, which nicely show how that clarifies the state of the conn in the
logs.

On errors, log them, but don't fail hard: if one conn use/un-use fails, we
don't want to crash the entire MSC before we have to.

Change-Id: I259aa0eec41efebb4c8221275219433eafaa549b

6 files changed, 62 insertions, 19 deletions

diff --git a/src/libmsc/gsm_04_08.c b/src/libmsc/gsm_04_08.c
index 5fab4090c..e783b5e63 100644
--- a/src/libmsc/gsm_04_08.c
+++ b/src/libmsc/gsm_04_08.c
@@ -2981,7 +2981,7 @@ int mncc_tx_to_cc(struct gsm_network *net, int msg_type, void *arg)
 		}
 
 		/* Assign conn */
-		trans->conn = msc_subscr_conn_get(conn);
+		trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_CC);
 		vlr_subscr_put(vsub);
 	} else {
 		/* update the subscriber we deal with */
@@ -3133,7 +3133,7 @@ static int gsm0408_rcv_cc(struct gsm_subscriber_connection *conn, struct msgb *m
 			return -ENOMEM;
 		}
 		/* Assign transaction */
-		trans->conn = msc_subscr_conn_get(conn);
+		trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_CC);
 		cm_service_request_concludes(conn, msg);
 	}
 
diff --git a/src/libmsc/gsm_04_11.c b/src/libmsc/gsm_04_11.c
index 103c259c2..50242a61b 100644
--- a/src/libmsc/gsm_04_11.c
+++ b/src/libmsc/gsm_04_11.c
@@ -949,7 +949,7 @@ int gsm0411_rcv_sms(struct gsm_subscriber_connection *conn,
 		gsm411_smr_init(&trans->sms.smr_inst, 0, 1,
 			gsm411_rl_recv, gsm411_mn_send);
 
-		trans->conn = msc_subscr_conn_get(conn);
+		trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_SMS);
 
 		new_trans = 1;
 		cm_service_request_concludes(conn, msg);
@@ -1031,7 +1031,7 @@ int gsm411_send_sms(struct gsm_subscriber_connection *conn, struct gsm_sms *sms)
 		gsm411_rl_recv, gsm411_mn_send);
 	trans->sms.sms = sms;
 
-	trans->conn = msc_subscr_conn_get(conn);
+	trans->conn = msc_subscr_conn_get(conn, MSC_CONN_USE_TRANS_SMS);
 
 	/* Hardcode SMSC Originating Address for now */
 	data = (uint8_t *)msgb_put(msg, 8);
diff --git a/src/libmsc/osmo_msc.c b/src/libmsc/osmo_msc.c
index f807f2aee..d55940d9c 100644
--- a/src/libmsc/osmo_msc.c
+++ b/src/libmsc/osmo_msc.c
@@ -69,14 +69,14 @@ static void subscr_conn_bump(struct gsm_subscriber_connection *conn)
 int msc_compl_l3(struct gsm_subscriber_connection *conn,
 		 struct msgb *msg, uint16_t chosen_channel)
 {
-	msc_subscr_conn_get(conn);
+	msc_subscr_conn_get(conn, MSC_CONN_USE_COMPL_L3);
 	gsm0408_dispatch(conn, msg);
 
 	/* Bump whether the conn wants to be closed */
 	subscr_conn_bump(conn);
 
 	/* If this should be kept, the conn->conn_fsm has placed a use_count */
-	msc_subscr_conn_put(conn);
+	msc_subscr_conn_put(conn, MSC_CONN_USE_COMPL_L3);
 
 	/* Always return acceptance, because even if the conn was not accepted,
 	 * we assumed ownership of it and the caller shall not interfere with
@@ -104,12 +104,12 @@ int msc_compl_l3(struct gsm_subscriber_connection *conn,
 /* Receive a DTAP message from BSC */
 void msc_dtap(struct gsm_subscriber_connection *conn, uint8_t link_id, struct msgb *msg)
 {
-	msc_subscr_conn_get(conn);
+	msc_subscr_conn_get(conn, MSC_CONN_USE_DTAP);
 	gsm0408_dispatch(conn, msg);
 
 	/* Bump whether the conn wants to be closed */
 	subscr_conn_bump(conn);
-	msc_subscr_conn_put(conn);
+	msc_subscr_conn_put(conn, MSC_CONN_USE_DTAP);
 }
 
 /* Receive an ASSIGNMENT COMPLETE from BSC */
@@ -343,6 +343,7 @@ void msc_subscr_conn_close(struct gsm_subscriber_connection *conn,
 /* increment the ref-count. Needs to be called by every user */
 struct gsm_subscriber_connection *
 _msc_subscr_conn_get(struct gsm_subscriber_connection *conn,
+		     enum msc_subscr_conn_use balance_token,
 		     const char *file, int line)
 {
 	OSMO_ASSERT(conn);
@@ -350,36 +351,74 @@ _msc_subscr_conn_get(struct gsm_subscriber_connection *conn,
 	if (conn->in_release)
 		return NULL;
 
+	if (balance_token != MSC_CONN_USE_UNTRACKED) {
+		uint32_t flag = 1 << balance_token;
+		OSMO_ASSERT(balance_token < 32);
+		if (conn->use_tokens & flag)
+			LOGPSRC(DREF, LOGL_ERROR, file, line,
+				"%s: MSC conn use error: using an already used token: %s\n",
+				vlr_subscr_name(conn->vsub),
+				msc_subscr_conn_use_name(balance_token));
+		conn->use_tokens |= flag;
+	}
+
 	conn->use_count++;
 	LOGPSRC(DREF, LOGL_DEBUG, file, line,
-		"%s: MSC conn use + 1 == %u\n",
-		vlr_subscr_name(conn->vsub), conn->use_count);
+		"%s: MSC conn use + %s == %u (0x%x)\n",
+		vlr_subscr_name(conn->vsub), msc_subscr_conn_use_name(balance_token),
+		conn->use_count, conn->use_tokens);
 
 	return conn;
 }
 
 /* decrement the ref-count. Once it reaches zero, we release */
 void _msc_subscr_conn_put(struct gsm_subscriber_connection *conn,
+			  enum msc_subscr_conn_use balance_token,
 			  const char *file, int line)
 {
 	OSMO_ASSERT(conn);
 
+	if (balance_token != MSC_CONN_USE_UNTRACKED) {
+		uint32_t flag = 1 << balance_token;
+		OSMO_ASSERT(balance_token < 32);
+		if (!(conn->use_tokens & flag))
+			LOGPSRC(DREF, LOGL_ERROR, file, line,
+				"%s: MSC conn use error: freeing an unused token: %s\n",
+				vlr_subscr_name(conn->vsub),
+				msc_subscr_conn_use_name(balance_token));
+		conn->use_tokens &= ~flag;
+	}
+
 	if (conn->use_count == 0) {
 		LOGPSRC(DREF, LOGL_ERROR, file, line,
-			"%s: MSC conn use - 1 failed: is already 0\n",
-			vlr_subscr_name(conn->vsub));
+			"%s: MSC conn use - %s failed: is already 0\n",
+			vlr_subscr_name(conn->vsub),
+			msc_subscr_conn_use_name(balance_token));
 		return;
 	}
 
 	conn->use_count--;
 	LOGPSRC(DREF, LOGL_DEBUG, file, line,
-		"%s: MSC conn use - 1 == %u\n",
-		vlr_subscr_name(conn->vsub), conn->use_count);
+		"%s: MSC conn use - %s == %u (0x%x)\n",
+		vlr_subscr_name(conn->vsub), msc_subscr_conn_use_name(balance_token),
+		conn->use_count, conn->use_tokens);
 
 	if (conn->use_count == 0)
 		msc_subscr_con_free(conn);
 }
 
+const struct value_string msc_subscr_conn_use_names[] = {
+	{MSC_CONN_USE_UNTRACKED,	"UNTRACKED"},
+	{MSC_CONN_USE_COMPL_L3,		"compl_l3"},
+	{MSC_CONN_USE_DTAP,		"dtap"},
+	{MSC_CONN_USE_FSM,		"fsm"},
+	{MSC_CONN_USE_TRANS_CC,		"trans_cc"},
+	{MSC_CONN_USE_TRANS_SMS,	"trans_sms"},
+	{MSC_CONN_USE_TRANS_USSD,	"trans_ussd"},
+	{MSC_CONN_USE_SILENT_CALL,	"silent_call"},
+	{0, NULL},
+};
+
 void msc_stop_paging(struct vlr_subscr *vsub)
 {
 	DEBUGP(DPAG, "Paging can stop for %s\n", vlr_subscr_name(vsub));
diff --git a/src/libmsc/silent_call.c b/src/libmsc/silent_call.c
index 5b197008b..b9a8ed90b 100644
--- a/src/libmsc/silent_call.c
+++ b/src/libmsc/silent_call.c
@@ -59,7 +59,7 @@ static int paging_cb_silent(unsigned int hooknum, unsigned int event,
 			conn->lchan->ts->nr, conn->lchan->ts->trx->arfcn);
 #endif
 		conn->silent_call = 1;
-		msc_subscr_conn_get(conn);
+		msc_subscr_conn_get(conn, MSC_CONN_USE_SILENT_CALL);
 		/* increment lchan reference count */
 		osmo_signal_dispatch(SS_SCALL, S_SCALL_SUCCESS, &sigdata);
 		break;
@@ -159,7 +159,7 @@ int gsm_silent_call_stop(struct vlr_subscr *vsub)
 #endif
 
 	conn->silent_call = 0;
-	msc_subscr_conn_put(conn);
+	msc_subscr_conn_put(conn, MSC_CONN_USE_SILENT_CALL);
 
 	return 0;
 }
diff --git a/src/libmsc/subscr_conn.c b/src/libmsc/subscr_conn.c
index 62b76195a..0fb4f5418 100644
--- a/src/libmsc/subscr_conn.c
+++ b/src/libmsc/subscr_conn.c
@@ -225,7 +225,7 @@ static void subscr_conn_fsm_cleanup(struct osmo_fsm_inst *fi,
 		return;
 	conn->conn_fsm = NULL;
  	msc_subscr_conn_close(conn, cause);
-	msc_subscr_conn_put(conn);
+	msc_subscr_conn_put(conn, MSC_CONN_USE_FSM);
 }
 
 int subscr_conn_fsm_timeout(struct osmo_fsm_inst *fi)
@@ -320,7 +320,7 @@ int msc_create_conn_fsm(struct gsm_subscriber_connection *conn, const char *id)
 	 * connection, then in _osmo_fsm_inst_term() the osmo_fsm_inst_free()
 	 * that follows the cleanup() call would run into a double free. */
 	fi = osmo_fsm_inst_alloc(&subscr_conn_fsm, conn->network,
-				 msc_subscr_conn_get(conn),
+				 msc_subscr_conn_get(conn, MSC_CONN_USE_FSM),
 				 LOGL_DEBUG, id);
 
 	if (!fi) {
diff --git a/src/libmsc/transaction.c b/src/libmsc/transaction.c
index 01d69c24e..4dcd24db1 100644
--- a/src/libmsc/transaction.c
+++ b/src/libmsc/transaction.c
@@ -117,12 +117,16 @@ 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;
+
 	switch (trans->protocol) {
 	case GSM48_PDISC_CC:
 		_gsm48_cc_trans_free(trans);
+		conn_usage_token = MSC_CONN_USE_TRANS_CC;
 		break;
 	case GSM48_PDISC_SMS:
 		_gsm411_sms_trans_free(trans);
+		conn_usage_token = MSC_CONN_USE_TRANS_SMS;
 		break;
 	}
 
@@ -139,7 +143,7 @@ void trans_free(struct gsm_trans *trans)
 	llist_del(&trans->entry);
 
 	if (trans->conn)
-		msc_subscr_conn_put(trans->conn);
+		msc_subscr_conn_put(trans->conn, conn_usage_token);
 
 	trans->conn = NULL;
 	talloc_free(trans);