refactor log ctx for vlr_subscr and ran_conn

ran_conn_get_conn_id(): instead of a talloc allocated string, return a static
buffer in ran_conn_get_conn_id(). So far this function had no callers.

Refactor ran_conn_update_id() API: during early L3-Complete, when no subscriber
is associated yet, update the FSM Id by the MI type seen in the L3 Complete
message: ran_conn_update_id_from_mi(). Later on set the vsub and re-update.

Call vlr.ops->subscr_update when the TMSI is updated, so that log context
includes the TMSI from then on.

Enrich context for vlr_subscr_name and ran_conn fi name.

Include all available information in vlr_subscr_name(); instead of either IMSI
or MSISDN or TMSI, print all of them when present. Instead of a short log,
rather have more valuable context.

A context info would now look like:

  Process_Access_Request_VLR(IMSI-901700000014706:MSISDN-2023:TMSI-0x08BDE4EC:GERAN-A-3:PAGING_RESP)

It does get quite long, but ensures easy correlation of any BSSAP / IuCS
messages with log output, especially if multiple subscribers are busy at the
same time.

Print TMSI and TMSInew in uppercase hexadecimal, which is the typical
representation in the telecom world.

When showing the RAN conn id
  GERAN_A-00000017
becomes
  GERAN-A-23
- We usually write the conn_id in decimal.
- Leading zeros are clutter and might suggest hexadecimal format.
- 'GERAN-A' and 'UTRAN-Iu' are the strings defined by osmo_rat_type_name().

Depends: I7798c3ef983c2e333b2b9cbffef6f366f370bd81 (libosmocore)
Depends: Ica25919758ef6cba8348da199b0ae7e0ba628798 (libosmocore)
Change-Id: I66a68ce2eb8957a35855a3743d91a86299900834

5 files changed, 111 insertions, 53 deletions

diff --git a/src/libmsc/gsm_04_08.c b/src/libmsc/gsm_04_08.c
index 646e9a017..980f6689d 100644
--- a/src/libmsc/gsm_04_08.c
+++ b/src/libmsc/gsm_04_08.c
@@ -326,10 +326,6 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 
  	lu = (struct gsm48_loc_upd_req *) gh->data;
 
-	mi_type = lu->mi[0] & GSM_MI_TYPE_MASK;
-
-	gsm48_mi_to_string(mi_string, sizeof(mi_string), lu->mi, lu->mi_len);
-
 	if (ran_conn_is_establishing_auth_ciph(conn)) {
 		LOG_RAN_CONN_CAT(conn, DMM, LOGL_ERROR,
 				 "Cannot accept another LU, conn already busy establishing authenticity;"
@@ -346,7 +342,8 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 		return -EINVAL;
 	}
 
-	ran_conn_update_id(conn, COMPLETE_LAYER3_LU, mi_string);
+	conn->complete_layer3_type = COMPLETE_LAYER3_LU;
+	ran_conn_update_id_from_mi(conn, lu->mi, lu->mi_len);
 
 	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));
@@ -373,6 +370,8 @@ int mm_rx_loc_upd_req(struct ran_conn *conn, struct msgb *msg)
 	/* TODO: 10.5.7.8 Device properties */
 	/* TODO: 10.5.1.15 MS network feature support */
 
+	mi_type = lu->mi[0] & GSM_MI_TYPE_MASK;
+	gsm48_mi_to_string(mi_string, sizeof(mi_string), lu->mi, lu->mi_len);
 	switch (mi_type) {
 	case GSM_MI_TYPE_IMSI:
 		tmsi = GSM_RESERVED_TMSI;
@@ -677,7 +676,7 @@ accept_reuse:
 		conn->received_cm_service_request = true;
 		ran_conn_get(conn, RAN_CONN_USE_CM_SERVICE);
 	}
-	ran_conn_update_id(conn, conn->complete_layer3_type, mi_string);
+	ran_conn_update_id(conn);
 	return conn->network->vlr->ops.tx_cm_serv_acc(conn);
 }
 
@@ -696,8 +695,6 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 {
 	struct gsm_network *net = conn->network;
 	uint8_t mi_type;
-	char mi_string[GSM48_MI_SIZE];
-
 	struct gsm48_hdr *gh = msgb_l3(msg);
 	struct gsm48_service_request *req =
 			(struct gsm48_service_request *)gh->data;
@@ -734,12 +731,12 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 		/* or should we accept and note down the service request anyway? */
 	}
 
-	gsm48_mi_to_string(mi_string, sizeof(mi_string), mi, mi_len);
-
-	mi_type = mi[0] & GSM_MI_TYPE_MASK;
-	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);
+	conn->complete_layer3_type = COMPLETE_LAYER3_CM_SERVICE_REQ;
+	ran_conn_update_id_from_mi(conn, mi, mi_len);
+	LOG_RAN_CONN_CAT(conn, DMM, LOGL_DEBUG, "Rx CM SERVICE REQUEST cm_service_type=0x%02x\n",
+			 req->cm_service_type);
 
+	mi_type = (mi && mi_len) ? (mi[0] & GSM_MI_TYPE_MASK) : GSM_MI_TYPE_NONE;
 	switch (mi_type) {
 	case GSM_MI_TYPE_IMSI:
 	case GSM_MI_TYPE_TMSI:
@@ -753,7 +750,7 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 		}
 		/* fall-through for non-emergency setup */
 	default:
-		LOG_RAN_CONN(conn, LOGL_ERROR, "mi_type is not expected: %d\n", mi_type);
+		LOG_RAN_CONN(conn, LOGL_ERROR, "MI type is not expected: %s\n", gsm48_mi_type_name(mi_type));
 		return msc_gsm48_tx_mm_serv_rej(conn,
 						GSM48_REJECT_INCORRECT_MESSAGE);
 	}
@@ -772,9 +769,6 @@ int gsm48_rx_mm_serv_req(struct ran_conn *conn, struct msgb *msg)
 	if (ran_conn_is_accepted(conn))
 		return cm_serv_reuse_conn(conn, mi_p);
 
-
-	ran_conn_update_id(conn, COMPLETE_LAYER3_CM_SERVICE_REQ, mi_string);
-
 	osmo_signal_dispatch(SS_SUBSCR, S_SUBSCR_IDENTITY, mi_p);
 
 	is_utran = (conn->via_ran == OSMO_RAT_UTRAN_IU);
@@ -1142,25 +1136,15 @@ static int gsm48_rx_rr_pag_resp(struct ran_conn *conn, struct msgb *msg)
 {
 	struct gsm_network *net = conn->network;
 	struct gsm48_hdr *gh = msgb_l3(msg);
-	struct gsm48_pag_resp *resp;
 	uint8_t classmark2_len = gh->data[1];
 	uint8_t *classmark2 = gh->data+2;
 	uint8_t *mi_lv = classmark2 + classmark2_len;
-	uint8_t mi_type;
-	char mi_string[GSM48_MI_SIZE];
 	struct osmo_location_area_id lai;
 	bool is_utran;
 
 	lai.plmn = conn->network->plmn;
 	lai.lac = conn->lac;
 
-	resp = (struct gsm48_pag_resp *) &gh->data[0];
-
-	if (gsm48_paging_extract_mi(resp, msgb_l3len(msg) - sizeof(*gh), mi_string, &mi_type) <= 0) {
-		LOGP(DRR, LOGL_ERROR, "PAGING RESPONSE: invalid Mobile Identity\n");
-		return -EINVAL;
-	}
-
 	if (ran_conn_is_establishing_auth_ciph(conn)) {
 		LOGP(DMM, LOGL_ERROR,
 		     "Ignoring Paging Response, conn already busy establishing authenticity\n");
@@ -1172,8 +1156,9 @@ static int gsm48_rx_rr_pag_resp(struct ran_conn *conn, struct msgb *msg)
 		return 0;
 	}
 
-	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);
+	conn->complete_layer3_type = COMPLETE_LAYER3_PAGING_RESP;
+	ran_conn_update_id_from_mi(conn, mi_lv + 1, *mi_lv);
+	LOG_RAN_CONN_CAT(conn, DRR, LOGL_DEBUG, "PAGING RESPONSE\n");
 
 	is_utran = (conn->via_ran == OSMO_RAT_UTRAN_IU);
 	vlr_proc_acc_req(conn->fi,
@@ -1734,6 +1719,7 @@ static void msc_vlr_subscr_update(struct vlr_subscr *subscr)
 {
 	LOGVSUBP(LOGL_NOTICE, subscr, "VLR: update for IMSI=%s (MSISDN=%s, used=%d)\n",
 		 subscr->imsi, subscr->msisdn, subscr->use_count);
+	ran_conn_update_id_for_vsub(subscr);
 }
 
 static void update_classmark(const struct gsm_classmark *src, struct gsm_classmark *dst)
@@ -1777,6 +1763,7 @@ static int msc_vlr_subscr_assoc(void *msc_conn_ref,
 	 * associated with the conn: merge the new Classmark into vsub->classmark. Don't overwrite valid
 	 * vsub->classmark with unset classmark, though. */
 	update_classmark(&conn->temporary_classmark, &conn->vsub->classmark);
+	ran_conn_update_id(conn);
 	return 0;
 }
 
diff --git a/src/libmsc/iu_dummy.c b/src/libmsc/iu_dummy.c
index 3f11d94ce..277ec07db 100644
--- a/src/libmsc/iu_dummy.c
+++ b/src/libmsc/iu_dummy.c
@@ -91,8 +91,9 @@ int ranap_iu_tx_release(struct ranap_ue_conn_ctx *ctx, const struct RANAP_Cause
 
 uint32_t iu_get_conn_id(const struct ranap_ue_conn_ctx *ue)
 {
-	LOGP(DLGLOBAL, LOGL_INFO, "iu_get_conn_id() dummy called, returning BOGUS value\n");
-	return 23;
+	/* There is a bogus conn_id in the bogus struct ranap_ue_conn_ctx, managed for unit testing of Iu even in the
+	 * absence of libosmo-ranap (when built without Iu support). */
+	return ue->conn_id;
 }
 
 #endif
diff --git a/src/libmsc/ran_conn.c b/src/libmsc/ran_conn.c
index 714907fe6..dca8ce06a 100644
--- a/src/libmsc/ran_conn.c
+++ b/src/libmsc/ran_conn.c
@@ -491,22 +491,31 @@ static struct osmo_fsm ran_conn_fsm = {
 	.timer_cb = ran_conn_fsm_timeout,
 };
 
-char *ran_conn_get_conn_id(struct ran_conn *conn)
+/* Return statically allocated string of the ran_conn RAT type and id. */
+const char *ran_conn_get_conn_id(struct ran_conn *conn)
 {
-	char *id;
+	static char id[42];
+	int rc;
+	uint32_t conn_id;
 
 	switch (conn->via_ran) {
 	case OSMO_RAT_GERAN_A:
-		id = talloc_asprintf(conn, "GERAN_A-%08x", conn->a.conn_id);
+		conn_id = conn->a.conn_id;
 		break;
 	case OSMO_RAT_UTRAN_IU:
-		id = talloc_asprintf(conn, "UTRAN_IU-%08x", iu_get_conn_id(conn->iu.ue_ctx));
+		conn_id = iu_get_conn_id(conn->iu.ue_ctx);
 		break;
 	default:
-		LOGP(DMM, LOGL_ERROR, "RAN of conn %p unknown!\n", conn);
-		return NULL;
+		return "ran-unknown";
 	}
 
+	rc = snprintf(id, sizeof(id), "%s-%u", osmo_rat_type_name(conn->via_ran), conn_id);
+	/* < 0 is error, == 0 is empty, >= size means truncation. Not really expecting this to catch on in any practical
+	 * situation. */
+	if (rc <= 0 || rc >= sizeof(id)) {
+		LOGP(DMM, LOGL_ERROR, "Error with conn id; rc=%d\n", rc);
+		return "conn-id-error";
+	}
 	return id;
 }
 
@@ -684,12 +693,57 @@ const struct value_string complete_layer3_type_names[] = {
 	{ 0, NULL }
 };
 
-void ran_conn_update_id(struct ran_conn *conn,
-			       enum complete_layer3_type from, const char *id)
+static void _ran_conn_update_id(struct ran_conn *conn, const char *subscr_identity)
 {
-       conn->complete_layer3_type = from;
-       osmo_fsm_inst_update_id_f(conn->fi, "%s:%s", complete_layer3_type_name(from), id);
-       LOGPFSML(conn->fi, LOGL_DEBUG, "Updated ID\n");
+	struct vlr_subscr *vsub = conn->vsub;
+
+	if (osmo_fsm_inst_update_id_f(conn->fi, "%s:%s:%s",
+				      subscr_identity,
+				      ran_conn_get_conn_id(conn),
+				      complete_layer3_type_name(conn->complete_layer3_type))
+	    != 0)
+		return; /* osmo_fsm_inst_update_id_f() will log an error. */
+
+	if (vsub) {
+		if (vsub->lu_fsm)
+			osmo_fsm_inst_update_id(vsub->lu_fsm, conn->fi->id);
+		if (vsub->auth_fsm)
+			osmo_fsm_inst_update_id(vsub->auth_fsm, conn->fi->id);
+		if (vsub->proc_arq_fsm)
+			osmo_fsm_inst_update_id(vsub->proc_arq_fsm, conn->fi->id);
+	}
+
+	LOGPFSML(conn->fi, LOGL_DEBUG, "Updated ID\n");
+}
+
+/* Compose an ID almost like gsm48_mi_to_string(), but print the MI type along, and print a TMSI as hex. */
+void ran_conn_update_id_from_mi(struct ran_conn *conn, const uint8_t *mi, uint8_t mi_len)
+{
+	_ran_conn_update_id(conn, osmo_mi_name(mi, mi_len));
+}
+
+/* Update ran_conn->fi id string from current conn->vsub and conn->complete_layer3_type. */
+void ran_conn_update_id(struct ran_conn *conn)
+{
+	_ran_conn_update_id(conn, vlr_subscr_name(conn->vsub));
+}
+
+/* Iterate all ran_conn instances that are relevant for this subscriber, and update FSM ID strings for all of the FSM
+ * instances. */
+void ran_conn_update_id_for_vsub(struct vlr_subscr *for_vsub)
+{
+	struct gsm_network *network;
+	struct ran_conn *conn;
+	if (!for_vsub)
+		return;
+
+	network = for_vsub->vlr->user_ctx;
+	OSMO_ASSERT(network);
+
+	llist_for_each_entry(conn, &network->ran_conns, entry) {
+		if (conn->vsub == for_vsub)
+			ran_conn_update_id(conn);
+	}
 }
 
 static void rx_close_complete(struct ran_conn *conn, const char *label, bool *flag)
diff --git a/src/libvlr/vlr.c b/src/libvlr/vlr.c
index b0e7f7906..887602c10 100644
--- a/src/libvlr/vlr.c
+++ b/src/libvlr/vlr.c
@@ -81,20 +81,34 @@ uint32_t vlr_timer(struct vlr_instance *vlr, uint32_t timer)
 /* return static buffer with printable name of VLR subscriber */
 const char *vlr_subscr_name(const struct vlr_subscr *vsub)
 {
-	static char buf[32];
+	static char buf[128];
+	char imsi[23] = "";
+	char msisdn[25] = "";
+	char tmsi[23] = "";
+	char tmsi_new[23] = "";
+	bool present = false;
 	if (!vsub)
 		return "unknown";
-	if (vsub->msisdn[0])
-		snprintf(buf, sizeof(buf), "MSISDN:%s", vsub->msisdn);
-	else if (vsub->imsi[0])
-		snprintf(buf, sizeof(buf), "IMSI:%s", vsub->imsi);
-	else if (vsub->tmsi != GSM_RESERVED_TMSI)
-		snprintf(buf, sizeof(buf), "TMSI:0x%08x", vsub->tmsi);
-	else if (vsub->tmsi_new != GSM_RESERVED_TMSI)
-		snprintf(buf, sizeof(buf), "TMSI(new):0x%08x", vsub->tmsi_new);
-	else
+	if (vsub->imsi[0]) {
+		snprintf(imsi, sizeof(imsi), "IMSI-%s", vsub->imsi);
+		present = true;
+	}
+	if (vsub->msisdn[0]) {
+		snprintf(msisdn, sizeof(msisdn), "%sMSISDN-%s", present? ":" : "", vsub->msisdn);
+		present = true;
+	}
+	if (vsub->tmsi != GSM_RESERVED_TMSI) {
+		snprintf(tmsi, sizeof(tmsi), "%sTMSI-0x%08X", present? ":" : "", vsub->tmsi);
+		present = true;
+	}
+	if (vsub->tmsi_new != GSM_RESERVED_TMSI) {
+		snprintf(tmsi_new, sizeof(tmsi_new), "%sTMSInew-0x%08X", present? ":" : "", vsub->tmsi_new);
+		present = true;
+	}
+	if (!present)
 		return "unknown";
-	buf[sizeof(buf)-1] = '\0';
+
+	snprintf(buf, sizeof(buf), "%s%s%s%s", imsi, msisdn, tmsi, tmsi_new);
 	return buf;
 }
 
@@ -329,6 +343,7 @@ int vlr_subscr_alloc_tmsi(struct vlr_subscr *vsub)
 			continue;
 
 		vsub->tmsi_new = tmsi;
+		vsub->vlr->ops.subscr_update(vsub);
 		return 0;
 	}
 
diff --git a/src/libvlr/vlr_lu_fsm.c b/src/libvlr/vlr_lu_fsm.c
index b00f8cef0..8640d2b14 100644
--- a/src/libvlr/vlr_lu_fsm.c
+++ b/src/libvlr/vlr_lu_fsm.c
@@ -547,6 +547,7 @@ static void lu_compl_vlr_wait_tmsi(struct osmo_fsm_inst *fi, uint32_t event,
 
 	vsub->tmsi = vsub->tmsi_new;
 	vsub->tmsi_new = GSM_RESERVED_TMSI;
+	vsub->vlr->ops.subscr_update(vsub);
 
 	vlr_lu_compl_fsm_success(fi);
 }