Change in osmo-msc[master]: a_iface_bssap: add context information to log output

This is merely a historical archive of years 2008-2021, before the migration to mailman3.

A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.

dexter gerrit-no-reply at lists.osmocom.org
Tue Mar 19 13:55:07 UTC 2019


dexter has uploaded this change for review. ( https://gerrit.osmocom.org/13319


Change subject: a_iface_bssap: add context information to log output
......................................................................

a_iface_bssap: add context information to log output

At the moment many of the log statements in a_iface_bssap.c are just
LOGP statements without futrher context information. Since those
messages appear at a point where no related ran conn can be identified,
lets use the BSC as context information, so that the origin of those
messages can be traced back to at least one specific BSC.

Change-Id: I704954edc8677688fc7cccd2b23d2aff958ebf32
---
M src/libmsc/a_iface_bssap.c
M tests/msc_vlr/msc_vlr_test_gsm_ciph.c
M tests/msc_vlr/msc_vlr_test_gsm_ciph.err
3 files changed, 70 insertions(+), 42 deletions(-)



  git pull ssh://gerrit.osmocom.org:29418/osmo-msc refs/changes/19/13319/1

diff --git a/src/libmsc/a_iface_bssap.c b/src/libmsc/a_iface_bssap.c
index cb245b8..f57f449 100644
--- a/src/libmsc/a_iface_bssap.c
+++ b/src/libmsc/a_iface_bssap.c
@@ -43,10 +43,31 @@
 
 #define LOGPCONN LOG_RAN_CONN
 
+#define LOGPBSC(ss, level, a_conn_info, fmt, args ...) \
+	LOGP(ss, level, "BSC(%s) " fmt, bsc_name_by_conn_info(a_conn_info), ## args)
+
 /*
  * Helper functions to lookup and allocate subscribers
  */
 
+/* Get a human readble string that describes the SCCP address of the BSC */
+static char *bsc_name_by_conn_info(const struct a_conn_info *a_conn_info)
+{
+	struct gsm_network *network;
+	struct osmo_ss7_instance *ss7;
+	char *bsc_name;
+	if (!a_conn_info)
+		return "INVALID CONN INFO!";
+	network = a_conn_info->network;
+	ss7 = osmo_ss7_instance_find(network->a.cs7_instance);
+	if (!ss7)
+		return "INVALID SS7 INSTANCE!";
+	bsc_name = osmo_sccp_addr_name(ss7, &a_conn_info->bsc->bsc_addr);
+	if (!bsc_name)
+		return "INVALID BSC ADDRESS!";
+	return bsc_name;
+}
+
 /* Allocate a new RAN connection */
 static struct ran_conn *ran_conn_allocate_a(const struct a_conn_info *a_conn_info,
 								struct gsm_network *network,
@@ -54,7 +75,7 @@
 {
 	struct ran_conn *conn;
 
-	LOGP(DMSC, LOGL_DEBUG, "Allocating A-Interface RAN conn: lac %i, conn_id %i\n", lac, conn_id);
+	LOGPBSC(DMSC, LOGL_DEBUG, a_conn_info, "Allocating A-Interface RAN conn: lac %i, conn_id %i\n", lac, conn_id);
 
 	conn = ran_conn_alloc(network, OSMO_RAT_GERAN_A, lac);
 	if (!conn)
@@ -73,13 +94,15 @@
 
 /* Return an existing A RAN connection record for the given
  * connection IDs, or return NULL if not found. */
-static struct ran_conn *ran_conn_lookup_a(const struct gsm_network *network, int conn_id)
+static struct ran_conn *ran_conn_lookup_a(const struct a_conn_info *a_conn_info)
 {
+	struct gsm_network *network = a_conn_info->network;
+	int conn_id = a_conn_info->conn_id;
 	struct ran_conn *conn;
 
 	OSMO_ASSERT(network);
 
-	DEBUGP(DMSC, "Looking for A subscriber: conn_id %i\n", conn_id);
+	LOGPBSC(DMSC, LOGL_DEBUG, a_conn_info, "Looking for A subscriber: conn_id %i\n", conn_id);
 
 	/* FIXME: log_subscribers() is defined in iucs.c as static inline, if
 	 * maybe this function should be public to reach it from here? */
@@ -91,7 +114,7 @@
 			return conn;
 		}
 	}
-	DEBUGP(DMSC, "No A subscriber found for conn_id %i\n", conn_id);
+	LOGPBSC(DMSC, LOGL_DEBUG, a_conn_info, "No A subscriber found for conn_id %i\n", conn_id);
 	return NULL;
 }
 
@@ -108,8 +131,8 @@
 	ss7 = osmo_ss7_instance_find(network->a.cs7_instance);
 	OSMO_ASSERT(ss7);
 
-	LOGP(DBSSAP, LOGL_NOTICE, "Rx BSSMAP RESET from BSC %s, sending RESET ACK\n",
-	     osmo_sccp_addr_name(ss7, &a_conn_info->bsc->bsc_addr));
+	LOGPBSC(DBSSAP, LOGL_NOTICE, a_conn_info, "Rx BSSMAP RESET from BSC %s, sending RESET ACK\n",
+		osmo_sccp_addr_name(ss7, &a_conn_info->bsc->bsc_addr));
 	osmo_sccp_tx_unitdata_msg(scu, &a_conn_info->bsc->msc_addr, &a_conn_info->bsc->bsc_addr,
 				  gsm0808_create_reset_ack());
 
@@ -136,12 +159,12 @@
 	OSMO_ASSERT(ss7);
 
 	if (a_conn_info->bsc->reset_fsm == NULL) {
-		LOGP(DBSSAP, LOGL_ERROR, "Received RESET ACK from an unknown BSC %s, ignoring...\n",
-		     osmo_sccp_addr_name(ss7, &a_conn_info->bsc->bsc_addr));
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info, "Received RESET ACK from an unknown BSC %s, ignoring...\n",
+			osmo_sccp_addr_name(ss7, &a_conn_info->bsc->bsc_addr));
 		return;
 	}
 
-	LOGP(DBSSAP, LOGL_NOTICE, "Received RESET ACK from BSC %s\n",
+	LOGPBSC(DBSSAP, LOGL_NOTICE, a_conn_info, "Received RESET ACK from BSC %s\n",
 		osmo_sccp_addr_name(ss7, &a_conn_info->bsc->bsc_addr));
 
 	/* Confirm that we managed to get the reset ack message
@@ -156,11 +179,11 @@
 	 * can be received via UNITDATA */
 
 	if (msgb_l3len(msg) < 1) {
-		LOGP(DBSSAP, LOGL_NOTICE, "Error: No data received -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_NOTICE, a_conn_info, "Error: No data received -- discarding message!\n");
 		return;
 	}
 
-	LOGP(DBSSAP, LOGL_DEBUG, "Rx BSSMAP UDT %s\n", gsm0808_bssmap_name(msg->l3h[0]));
+	LOGPBSC(DBSSAP, LOGL_DEBUG, a_conn_info, "Rx BSSMAP UDT %s\n", gsm0808_bssmap_name(msg->l3h[0]));
 
 	switch (msg->l3h[0]) {
 	case BSS_MAP_MSG_RESET:
@@ -170,7 +193,7 @@
 		bssmap_rx_reset_ack(scu, a_conn_info, msg);
 		break;
 	default:
-		LOGP(DBSSAP, LOGL_NOTICE, "Unimplemented message format: %s -- message discarded!\n",
+		LOGPBSC(DBSSAP, LOGL_NOTICE, a_conn_info, "Unimplemented message format: %s -- message discarded!\n",
 		     gsm0808_bssmap_name(msg->l3h[0]));
 	}
 }
@@ -186,16 +209,16 @@
 	OSMO_ASSERT(a_conn_info);
 	OSMO_ASSERT(msg);
 
-	LOGP(DBSSAP, LOGL_DEBUG, "Rx BSSMAP UDT: %s\n", msgb_hexdump_l2(msg));
+	LOGPBSC(DBSSAP, LOGL_DEBUG, a_conn_info, "Rx BSSMAP UDT: %s\n", msgb_hexdump_l2(msg));
 
 	if (msgb_l2len(msg) < sizeof(*bs)) {
-		LOGP(DBSSAP, LOGL_ERROR, "Error: Header is too short -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info, "Error: Header is too short -- discarding message!\n");
 		return;
 	}
 
 	bs = (struct bssmap_header *)msgb_l2(msg);
 	if (bs->length < msgb_l2len(msg) - sizeof(*bs)) {
-		LOGP(DBSSAP, LOGL_ERROR, "Error: Message is too short -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info, "Error: Message is too short -- discarding message!\n");
 		return;
 	}
 
@@ -205,7 +228,7 @@
 		bssmap_rcvmsg_udt(scu, a_conn_info, msg);
 		break;
 	default:
-		LOGP(DBSSAP, LOGL_ERROR,
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
 		     "Error: Unimplemented message type: %s -- message discarded!\n", gsm0808_bssmap_name(bs->type));
 	}
 }
@@ -223,7 +246,7 @@
 	LOGPCONN(conn, LOGL_INFO, "Rx BSSMAP CLEAR REQUEST\n");
 
 	if (!TLVP_PRESENT(tp, GSM0808_IE_CAUSE)) {
-		LOGP(DBSSAP, LOGL_ERROR, "Cause code is missing -- discarding message!\n");
+		LOGPCONN(conn, LOGL_ERROR, "Cause code is missing -- discarding message!\n");
 		return -EINVAL;
 	}
 	cause = TLVP_VAL(tp, GSM0808_IE_CAUSE)[0];
@@ -265,14 +288,16 @@
 	struct gsm_network *network = a_conn_info->network;
 	struct ran_conn *conn;
 
-	LOGP(DBSSAP, LOGL_INFO, "Rx BSSMAP COMPLETE L3 INFO (conn_id=%i)\n", a_conn_info->conn_id);
+	LOGPBSC(DBSSAP, LOGL_INFO, a_conn_info, "Rx BSSMAP COMPLETE L3 INFO (conn_id=%i)\n", a_conn_info->conn_id);
 
 	if (!TLVP_PRESENT(tp, GSM0808_IE_CELL_IDENTIFIER)) {
-		LOGP(DBSSAP, LOGL_ERROR, "Mandatory CELL IDENTIFIER not present -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+			"Mandatory CELL IDENTIFIER not present -- discarding message!\n");
 		return -EINVAL;
 	}
 	if (!TLVP_PRESENT(tp, GSM0808_IE_LAYER_3_INFORMATION)) {
-		LOGP(DBSSAP, LOGL_ERROR, "Mandatory LAYER 3 INFORMATION not present -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+			"Mandatory LAYER 3 INFORMATION not present -- discarding message!\n");
 		return -EINVAL;
 	}
 
@@ -281,8 +306,8 @@
 	data_length = TLVP_LEN(tp, GSM0808_IE_CELL_IDENTIFIER);
 	data = TLVP_VAL(tp, GSM0808_IE_CELL_IDENTIFIER);
 	if (gsm0808_dec_cell_id_list2(&cil, data, data_length) < 0 || cil.id_list_len != 1) {
-		LOGP(DBSSAP, LOGL_ERROR,
-		     "Unable to parse element CELL IDENTIFIER -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+			"Unable to parse element CELL IDENTIFIER -- discarding message!\n");
 		return -EINVAL;
 	}
 
@@ -291,8 +316,8 @@
 	case CELL_IDENT_WHOLE_GLOBAL: {
 		const struct osmo_cell_global_id *id = &cil.id_list[0].global;
 		if (osmo_plmn_cmp(&id->lai.plmn, &network->plmn) != 0) {
-			LOGP(DBSSAP, LOGL_ERROR,
-			     "WHOLE GLOBAL CELL IDENTIFIER does not match network MCC/MNC -- discarding message!\n");
+			LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+				"WHOLE GLOBAL CELL IDENTIFIER does not match network MCC/MNC -- discarding message!\n");
 			return -EINVAL;
 		}
 		lac = id->lai.lac;
@@ -306,8 +331,8 @@
 	case CELL_IDENT_LAI_AND_LAC: {
 		const struct osmo_location_area_id *id = &cil.id_list[0].lai_and_lac;
 		if (osmo_plmn_cmp(&id->plmn, &network->plmn) != 0) {
-			LOGP(DBSSAP, LOGL_ERROR,
-			     "LAI AND LAC CELL IDENTIFIER does not match network MCC/MNC -- discarding message!\n");
+			LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+				"LAI AND LAC CELL IDENTIFIER does not match network MCC/MNC -- discarding message!\n");
 			return -EINVAL;
 		}
 		lac = id->lac;
@@ -320,14 +345,14 @@
 	case CELL_IDENT_CI:
 	case CELL_IDENT_NO_CELL:
 	case CELL_IDENT_BSS:
-		LOGP(DBSSAP, LOGL_ERROR,
-		     "CELL IDENTIFIER does not specify a LAC -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+			"CELL IDENTIFIER does not specify a LAC -- discarding message!\n");
 		return -EINVAL;
 
 	default:
-		LOGP(DBSSAP, LOGL_ERROR,
-		     "Unable to parse element CELL IDENTIFIER (unknown cell identification discriminator 0x%x) "
-		     "-- discarding message!\n", cil.id_discr);
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info,
+			"Unable to parse element CELL IDENTIFIER (unknown cell identification discriminator 0x%x) "
+			"-- discarding message!\n", cil.id_discr);
 		return -EINVAL;
 	}
 
@@ -336,7 +361,7 @@
 	msgb_l3trim(msg, TLVP_LEN(tp, GSM0808_IE_LAYER_3_INFORMATION));
 
 	if (msgb_l3len(msg) < sizeof(struct gsm48_hdr)) {
-		LOGP(DBSSAP, LOGL_ERROR, "COMPL_L3 with too short L3 (%d) -- discarding\n",
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info, "COMPL_L3 with too short L3 (%d) -- discarding\n",
 		     msgb_l3len(msg));
 		return -ENODATA;
 	}
@@ -617,14 +642,14 @@
 	uint8_t msg_type;
 
 	if (msgb_l3len(msg) < 1) {
-		LOGP(DBSSAP, LOGL_NOTICE, "Error: No data received -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_NOTICE, a_conn_info, "Error: No data received -- discarding message!\n");
 		return -1;
 	}
 	msg_type = msg->l3h[0];
 
 	rc = osmo_bssap_tlv_parse(&tp, msg->l3h + 1, msgb_l3len(msg) - 1);
 	if (rc < 0) {
-		LOGP(DBSSAP, LOGL_ERROR, "Failed parsing TLV -- discarding message! %s\n",
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info, "Failed parsing TLV -- discarding message! %s\n",
 			osmo_hexdump(msg->l3h, msgb_l3len(msg)));
 		return -EINVAL;
 	}
@@ -637,7 +662,7 @@
 		break;
 	}
 
-	conn = ran_conn_lookup_a(a_conn_info->network, a_conn_info->conn_id);
+	conn = ran_conn_lookup_a(a_conn_info);
 	if (!conn) {
 		LOGP(DBSSAP, LOGL_ERROR, "Couldn't find ran_conn for conn_id=%d\n", a_conn_info->conn_id);
 		/* We expect a Clear Complete to come in on a valid conn. But if for some reason we still
@@ -682,11 +707,10 @@
 /* Endpoint to handle regular BSSAP DTAP messages. No ownership of 'msg' is passed on! */
 static int rx_dtap(const struct osmo_sccp_user *scu, const struct a_conn_info *a_conn_info, struct msgb *msg)
 {
-	struct gsm_network *network = a_conn_info->network;
 	struct ran_conn *conn;
 	struct dtap_header *dtap = (struct dtap_header *) msg->l2h;
 
-	conn = ran_conn_lookup_a(network, a_conn_info->conn_id);
+	conn = ran_conn_lookup_a(a_conn_info);
 	if (!conn) {
 		return -EINVAL;
 	}
@@ -711,7 +735,7 @@
 	OSMO_ASSERT(msg);
 
 	if (msgb_l2len(msg) < sizeof(struct bssmap_header)) {
-		LOGP(DBSSAP, LOGL_NOTICE, "The header is too short -- discarding message!\n");
+		LOGPBSC(DBSSAP, LOGL_NOTICE, a_conn_info, "The header is too short -- discarding message!\n");
 		return -EINVAL;
 	}
 
@@ -722,7 +746,7 @@
 	case BSSAP_MSG_DTAP:
 		return rx_dtap(scu, a_conn_info, msg);
 	default:
-		LOGP(DBSSAP, LOGL_ERROR, "Unimplemented BSSAP msg type: %s\n", gsm0808_bssap_name(msg->l2h[0]));
+		LOGPBSC(DBSSAP, LOGL_ERROR, a_conn_info, "Unimplemented BSSAP msg type: %s\n", gsm0808_bssap_name(msg->l2h[0]));
 		return -EINVAL;
 	}
 
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.c b/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
index 19092e2..3ed22ee 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
@@ -1073,6 +1073,8 @@
 
 	comment_start();
 
+	osmo_ss7_init();
+
 	/* implicit: net->authentication_required = true; */
 	net->a5_encryption_mask = (1 << 3); /* A5/3 */
 
@@ -1292,6 +1294,8 @@
 
 	comment_start();
 
+	osmo_ss7_init();
+
 	/* A5/3 support is indicated in Classmark 3. By configuring A5/3, trigger the code paths that
 	 * send a Classmark Request. */
 	net->a5_encryption_mask = (1 << 3); /* A5/3 */
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
index ef77391..16300de 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
@@ -2461,7 +2461,7 @@
 DMM RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
   lu_result_sent == 0
 - BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3
-DMSC Looking for A subscriber: conn_id 0
+DMSC BSC(INVALID SS7 INSTANCE!) Looking for A subscriber: conn_id 0
 DBSSAP RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Found A subscriber for conn_id 0
 DBSSAP RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Rx BSSMAP DT1 CLASSMARK UPDATE
 DBSSAP RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Rx BSSMAP CLASSMARK UPDATE
@@ -2997,7 +2997,7 @@
 DMM RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
   lu_result_sent == 0
 - BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3
-DMSC Looking for A subscriber: conn_id 0
+DMSC BSC(INVALID SS7 INSTANCE!) Looking for A subscriber: conn_id 0
 DBSSAP RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Found A subscriber for conn_id 0
 DBSSAP RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Rx BSSMAP DT1 CLASSMARK UPDATE
 DBSSAP RAN_conn(IMSI-901700000004620:GERAN-A-0:LU){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Rx BSSMAP CLASSMARK UPDATE
@@ -3305,7 +3305,7 @@
 DMM RAN_conn(IMSI-901700000004620:MSISDN-42342:GERAN-A-0:PAGING_RESP){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event RAN_CONN_E_UNUSED
 DMM RAN_conn(IMSI-901700000004620:MSISDN-42342:GERAN-A-0:PAGING_RESP){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
 - BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3
-DMSC Looking for A subscriber: conn_id 0
+DMSC BSC(INVALID SS7 INSTANCE!) Looking for A subscriber: conn_id 0
 DBSSAP RAN_conn(IMSI-901700000004620:MSISDN-42342:GERAN-A-0:PAGING_RESP){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Found A subscriber for conn_id 0
 DBSSAP RAN_conn(IMSI-901700000004620:MSISDN-42342:GERAN-A-0:PAGING_RESP){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Rx BSSMAP DT1 CLASSMARK UPDATE
 DBSSAP RAN_conn(IMSI-901700000004620:MSISDN-42342:GERAN-A-0:PAGING_RESP){RAN_CONN_S_WAIT_CLASSMARK_UPDATE}: Rx BSSMAP CLASSMARK UPDATE

-- 
To view, visit https://gerrit.osmocom.org/13319
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings

Gerrit-Project: osmo-msc
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I704954edc8677688fc7cccd2b23d2aff958ebf32
Gerrit-Change-Number: 13319
Gerrit-PatchSet: 1
Gerrit-Owner: dexter <pmaier at sysmocom.de>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20190319/f16e6f68/attachment.htm>


More information about the gerrit-log mailing list