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 <pma...@sysmocom.de>
