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

2 files changed, 27 insertions, 11 deletions

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);
 }