add LOG_RAN_CONN() to use the conn->fi->id for context

For each conn, set a default logging category, to distinguish categories for
BSSMAP and RANAP based conns.

LOG_RAN_CONN(): log with the conn's default category,

LOG_RAN_CONN_CAT(): log with a manually set category (mostly for keeping
previous DMM logging on the same category).

In some places, replace LOGP() using manual context with LOG_RAN_CONN(), and
remove the manual context info, now provided by the conn->fi->id.

This is loosely related to inter-BSC and inter-MSC handover: to speed up
refactoring, I want to avoid the need for manual logging context and just use
this LOG_RAN_CONN().

Change-Id: I0a7809840428b1e028df6eb683bc5ffcc8df474a

4 files changed, 50 insertions, 35 deletions

diff --git a/src/libmsc/a_iface.c b/src/libmsc/a_iface.c
index ee938aa9f..0811734ad 100644
--- a/src/libmsc/a_iface.c
+++ b/src/libmsc/a_iface.c
@@ -40,9 +40,12 @@
 #include <osmocom/sccp/sccp_types.h>
 #include <osmocom/msc/a_reset.h>
 #include <osmocom/msc/vlr.h>
+#include <osmocom/msc/ran_conn.h>
 
 #include <errno.h>
 
+#define LOGPCONN LOG_RAN_CONN
+
 /* A pointer to the GSM network we work with. By the current paradigm,
  * there can only be one gsm_network per MSC. The pointer is set once
  * when calling a_init() */
@@ -86,7 +89,7 @@ void a_delete_bsc_con(uint32_t conn_id)
 
 	llist_for_each_entry_safe(conn, conn_temp, &active_connections, list) {
 		if (conn->conn_id == conn_id) {
-			LOGPBSCCONN(conn, LOGL_DEBUG, "Removing A-interface conn\n");
+			LOGP(DBSSAP, LOGL_DEBUG, "(conn%u) Removing A-interface conn\n", conn->conn_id);
 			llist_del(&conn->list);
 			talloc_free(conn);
 		}
diff --git a/src/libmsc/a_iface_bssap.c b/src/libmsc/a_iface_bssap.c
index 491f8d07c..41af93c04 100644
--- a/src/libmsc/a_iface_bssap.c
+++ b/src/libmsc/a_iface_bssap.c
@@ -35,11 +35,14 @@
 #include <osmocom/msc/a_reset.h>
 #include <osmocom/msc/transaction.h>
 #include <osmocom/msc/msc_mgcp.h>
+#include <osmocom/msc/ran_conn.h>
 
 #include <errno.h>
 
 #define IP_V4_ADDR_LEN 4
 
+#define LOGPCONN LOG_RAN_CONN
+
 /*
  * Helper functions to lookup and allocate subscribers
  */
diff --git a/src/libmsc/gsm_04_08.c b/src/libmsc/gsm_04_08.c
index 9ccc5d58c..60da27508 100644
--- a/src/libmsc/gsm_04_08.c
+++ b/src/libmsc/gsm_04_08.c
@@ -331,25 +331,25 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 	gsm48_mi_to_string(mi_string, sizeof(mi_string), lu->mi, lu->mi_len);
 
 	if (ran_conn_is_establishing_auth_ciph(conn)) {
-		LOGP(DMM, LOGL_ERROR,
-		     "Cannot accept another LU, conn already busy establishing authenticity;"
-		     " extraneous LOCATION UPDATING REQUEST: MI(%s)=%s type=%s\n",
-		     gsm48_mi_type_name(mi_type), mi_string, osmo_lu_type_name(lu->type));
+		LOG_RAN_CONN_CAT(conn, DMM, LOGL_ERROR,
+				 "Cannot accept another LU, conn already busy establishing authenticity;"
+				 " extraneous LOCATION UPDATING REQUEST: MI=%s LU-type=%s\n",
+				 osmo_mi_name(lu->mi, lu->mi_len), osmo_lu_type_name(lu->type));
 		return -EINVAL;
 	}
 
 	if (ran_conn_is_accepted(conn)) {
-		LOGP(DMM, LOGL_ERROR,
-		     "Cannot accept another LU, conn already established;"
-		     " extraneous LOCATION UPDATING REQUEST: MI(%s)=%s type=%s\n",
-		     gsm48_mi_type_name(mi_type), mi_string, osmo_lu_type_name(lu->type));
+		LOG_RAN_CONN_CAT(conn, DMM, LOGL_ERROR,
+				 "Cannot accept another LU, conn already established;"
+				 " extraneous LOCATION UPDATING REQUEST: MI=%s LU-type=%s\n",
+				 osmo_mi_name(lu->mi, lu->mi_len), osmo_lu_type_name(lu->type));
 		return -EINVAL;
 	}
 
 	ran_conn_update_id(conn, COMPLETE_LAYER3_LU, mi_string);
 
-	DEBUGP(DMM, "LOCATION UPDATING REQUEST: MI(%s)=%s type=%s\n",
-	       gsm48_mi_type_name(mi_type), mi_string, osmo_lu_type_name(lu->type));
+	LOG_RAN_CONN_CAT(conn, DMM, LOGL_DEBUG, "LOCATION UPDATING REQUEST: MI=%s LU-type=%s\n",
+			 osmo_mi_name(lu->mi, lu->mi_len), osmo_lu_type_name(lu->type));
 
 	osmo_signal_dispatch(SS_SUBSCR, S_SUBSCR_IDENTITY, &lu->mi_len);
 
@@ -383,7 +383,7 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 		imsi = NULL;
 		break;
 	default:
-		DEBUGPC(DMM, "unknown mobile identity type\n");
+		LOG_RAN_CONN_CAT(conn, DMM, LOGL_ERROR, "unknown mobile identity type\n");
 		tmsi = GSM_RESERVED_TMSI;
 		imsi = NULL;
 		break;
@@ -392,7 +392,7 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 	gsm48_decode_lai2(&lu->lai, &old_lai);
 	new_lai.plmn = conn->network->plmn;
 	new_lai.lac = conn->lac;
-	DEBUGP(DMM, "LU/new-LAC: %u/%u\n", old_lai.lac, new_lai.lac);
+	LOG_RAN_CONN_CAT(conn, DMM, LOGL_DEBUG, "LU/new-LAC: %u/%u\n", old_lai.lac, new_lai.lac);
 
 	is_utran = (conn->via_ran == OSMO_RAT_UTRAN_IU);
 	lu_fsm = vlr_loc_update(conn->fi,
@@ -405,7 +405,7 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 				is_utran,
 				net->vlr->cfg.assign_tmsi);
 	if (!lu_fsm) {
-		DEBUGP(DRR, "%s: Can't start LU FSM\n", mi_string);
+		LOG_RAN_CONN(conn, LOGL_ERROR, "Can't start LU FSM\n");
 		return 0;
 	}
 
@@ -414,9 +414,7 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 	 * already have been called and completed. Has an error occured? */
 
 	if (!conn->vsub || conn->vsub->lu_fsm != lu_fsm) {
-		LOGP(DRR, LOGL_ERROR,
-		     "%s: internal error during Location Updating attempt\n",
-		     mi_string);
+		LOG_RAN_CONN(conn, LOGL_ERROR, "internal error during Location Updating attempt\n");
 		return -EIO;
 	}
 
@@ -587,7 +585,7 @@ int gsm48_tx_mm_info(struct ran_conn *conn)
 		ptr8[2] = dst;
 	}
 
-	DEBUGP(DMM, "-> MM INFO\n");
+	LOG_RAN_CONN(conn, LOGL_DEBUG, "Tx MM INFO\n");
 
 	return gsm48_conn_sendmsg(msg, conn, NULL);
 }
@@ -607,7 +605,7 @@ int gsm48_tx_mm_auth_req(struct ran_conn *conn, uint8_t *rand,
 	struct gsm48_hdr *gh = (struct gsm48_hdr *) msgb_put(msg, sizeof(*gh));
 	struct gsm48_auth_req *ar = (struct gsm48_auth_req *) msgb_put(msg, sizeof(*ar));
 
-	DEBUGP(DMM, "-> AUTH REQ (rand = %s)\n", osmo_hexdump_nospc(rand, 16));
+	DEBUGP(DMM, "Tx AUTH REQ (rand = %s)\n", osmo_hexdump_nospc(rand, 16));
 	if (autn)
 		DEBUGP(DMM, "   AUTH REQ (autn = %s)\n", osmo_hexdump_nospc(autn, 16));
 
@@ -716,21 +714,23 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 	lai.lac = conn->lac;
 
 	if (msg->data_len < sizeof(struct gsm48_service_request*)) {
-		LOGP(DMM, LOGL_ERROR, "<- CM SERVICE REQUEST wrong sized message\n");
+		LOG_RAN_CONN(conn, LOGL_ERROR, "Rx CM SERVICE REQUEST: wrong message size (%u < %zu)\n",
+			     msg->data_len, sizeof(struct gsm48_service_request*));
 		return msc_gsm48_tx_mm_serv_rej(conn,
 						GSM48_REJECT_INCORRECT_MESSAGE);
 	}
 
 	if (msg->data_len < req->mi_len + 6) {
-		LOGP(DMM, LOGL_ERROR, "<- CM SERVICE REQUEST does not fit in packet\n");
+		LOG_RAN_CONN(conn, LOGL_ERROR, "Rx CM SERVICE REQUEST: message does not fit in packet\n");
 		return msc_gsm48_tx_mm_serv_rej(conn,
 						GSM48_REJECT_INCORRECT_MESSAGE);
 	}
 
 	gsm48_mi_to_string(mi_string, sizeof(mi_string), mi, mi_len);
+
 	mi_type = mi[0] & GSM_MI_TYPE_MASK;
-	DEBUGP(DMM, "<- CM SERVICE REQUEST serv_type=0x%02x MI(%s)=%s\n",
-	       req->cm_service_type, gsm48_mi_type_name(mi_type), mi_string);
+	LOG_RAN_CONN_CAT(conn, DMM, LOGL_DEBUG, "Rx CM SERVICE REQUEST cm_service_type=0x%02x MI(%s)=%s\n",
+			 req->cm_service_type, gsm48_mi_type_name(mi_type), mi_string);
 
 	switch (mi_type) {
 	case GSM_MI_TYPE_IMSI:
@@ -740,12 +740,12 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 	case GSM_MI_TYPE_IMEI:
 		if (req->cm_service_type == GSM48_CMSERV_EMERGENCY) {
 			/* We don't do emergency calls by IMEI */
-			LOGP(DMM, LOGL_NOTICE, "<- CM SERVICE REQUEST(IMEI=%s) rejected\n", mi_string);
+			LOG_RAN_CONN(conn, LOGL_NOTICE, "Tx CM SERVICE REQUEST REJECT\n");
 			return msc_gsm48_tx_mm_serv_rej(conn, GSM48_REJECT_IMEI_NOT_ACCEPTED);
 		}
 		/* fall-through for non-emergency setup */
 	default:
-		DEBUGPC(DMM, "mi_type is not expected: %d\n", mi_type);
+		LOG_RAN_CONN(conn, LOGL_ERROR, "mi_type is not expected: %d\n", mi_type);
 		return msc_gsm48_tx_mm_serv_rej(conn,
 						GSM48_REJECT_INCORRECT_MESSAGE);
 	}
@@ -789,8 +789,7 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 	/* From vlr_proc_acc_req() we expect an implicit dispatch of PR_ARQ_E_START we expect
 	 * msc_vlr_subscr_assoc() to already have been called and completed. Has an error occured? */
 	if (!conn->vsub) {
-		LOGP(DRR, LOGL_ERROR, "%s: subscriber not allowed to do a CM Service Request\n",
-		     mi_string);
+		LOG_RAN_CONN(conn, LOGL_ERROR, "subscriber not allowed to do a CM Service Request\n");
 		return -EIO;
 	}
 
@@ -1172,9 +1171,8 @@ static int gsm48_rx_rr_pag_resp(struct ran_conn *conn, struct msgb *msg)
 		return 0;
 	}
 
-	DEBUGP(DRR, "PAGING RESPONSE: MI(%s)=%s\n", gsm48_mi_type_name(mi_type), mi_string);
-
 	ran_conn_update_id(conn, COMPLETE_LAYER3_PAGING_RESP, mi_string);
+	LOG_RAN_CONN_CAT(conn, DRR, LOGL_DEBUG, "PAGING RESPONSE: MI(%s)=%s\n", gsm48_mi_type_name(mi_type), mi_string);
 
 	is_utran = (conn->via_ran == OSMO_RAT_UTRAN_IU);
 	vlr_proc_acc_req(conn->fi,
@@ -1189,8 +1187,7 @@ static int gsm48_rx_rr_pag_resp(struct ran_conn *conn, struct msgb *msg)
 	/* From vlr_proc_acc_req() we expect an implicit dispatch of PR_ARQ_E_START we expect
 	 * msc_vlr_subscr_assoc() to already have been called and completed. Has an error occured? */
 	if (!conn->vsub) {
-		LOGP(DRR, LOGL_ERROR, "%s: subscriber not allowed to do a Paging Response\n",
-		     mi_string);
+		LOG_RAN_CONN(conn, LOGL_ERROR, "subscriber not allowed to do a Paging Response\n");
 		return -EIO;
 	}
 
@@ -1762,11 +1759,11 @@ static int msc_vlr_subscr_assoc(void *msc_conn_ref,
 	OSMO_ASSERT(vsub);
 	if (conn->vsub) {
 		if (conn->vsub == vsub)
-			LOGPCONN(conn, LOGL_NOTICE, "msc_vlr_subscr_assoc(): conn already associated with %s\n",
-				 vlr_subscr_name(vsub));
+			LOG_RAN_CONN(conn, LOGL_NOTICE, "msc_vlr_subscr_assoc(): conn already associated with %s\n",
+				     vlr_subscr_name(vsub));
 		else {
-			LOGPCONN(conn, LOGL_ERROR, "msc_vlr_subscr_assoc(): conn already associated with a subscriber,"
-				 " cannot associate with %s\n", vlr_subscr_name(vsub));
+			LOG_RAN_CONN(conn, LOGL_ERROR, "msc_vlr_subscr_assoc(): conn already associated with a subscriber,"
+				     " cannot associate with %s\n", vlr_subscr_name(vsub));
 			return -EINVAL;
 		}
 	}
diff --git a/src/libmsc/ran_conn.c b/src/libmsc/ran_conn.c
index d6349ebd5..714907fe6 100644
--- a/src/libmsc/ran_conn.c
+++ b/src/libmsc/ran_conn.c
@@ -651,6 +651,18 @@ struct ran_conn *ran_conn_alloc(struct gsm_network *network,
 		.fi = fi,
 	};
 
+	switch (via_ran) {
+	case OSMO_RAT_GERAN_A:
+		conn->log_subsys = DBSSAP;
+		break;
+	case OSMO_RAT_UTRAN_IU:
+		conn->log_subsys = DRANAP;
+		break;
+	default:
+		conn->log_subsys = DMSC;
+		break;
+	}
+
 	fi->priv = conn;
 	llist_add_tail(&conn->entry, &network->ran_conns);
 	return conn;