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
diff --git a/src/libmsc/gsm_04_08.c b/src/libmsc/gsm_04_08.c
index 646e9a0..980f668 100644
--- a/src/libmsc/gsm_04_08.c
+++ b/src/libmsc/gsm_04_08.c
@@ -326,10 +326,6 @@
 
  	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 @@
 		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 @@
 	/* 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 @@
 		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 @@
 {
 	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 @@
 		/* or should we accept and note down the service request anyway? */
 	}
 
-	gsm48_mi_to_string(mi_string, sizeof(mi_string), mi, mi_len);
+	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[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);
-
+	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 @@
 		}
 		/* 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 @@
 	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 @@
 {
 	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 @@
 		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 @@
 {
 	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 @@
 	 * 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;
 }