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/.
Neels Hofmeyr gerrit-no-reply at lists.osmocom.org
Review at https://gerrit.osmocom.org/7996
bsc_api.c: actually log with context
bsc_api.c notoriously lacks log context. Provide gsm_lchan_name() and/or
bsc_subscr_name() in roughly a million instances, using new LOGPLCHAN macro.
Change-Id: If469defcc6fe8950dac5df61db3f39d297893318
---
M src/libbsc/bsc_api.c
1 file changed, 57 insertions(+), 43 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/osmo-bsc refs/changes/96/7996/1
diff --git a/src/libbsc/bsc_api.c b/src/libbsc/bsc_api.c
index 142efef..f126bd4 100644
--- a/src/libbsc/bsc_api.c
+++ b/src/libbsc/bsc_api.c
@@ -44,6 +44,13 @@
#define HO_DTAP_CACHE_MSGB_CB_LINK_ID 0
#define HO_DTAP_CACHE_MSGB_CB_ALLOW_SACCH 1
+#define LOGPLCHAN(lchan, ss, level, fmt, args...) \
+ LOGP(ss, level, "%s%s (%s) " fmt, \
+ lchan ? gsm_lchan_name(lchan) : "-", \
+ lchan ? gsm_lchant_name(lchan->type) : "", \
+ bsc_subscr_name(lchan && lchan->conn ? lchan->conn->bsub : NULL), \
+ ## args)
+
static void rll_ind_cb(struct gsm_lchan *, uint8_t, void *, enum bsc_rllr_ind);
static void send_sapi_reject(struct gsm_subscriber_connection *conn, int link_id);
static void handle_release(struct gsm_subscriber_connection *conn, struct bsc_api *bsc, struct gsm_lchan *lchan);
@@ -117,17 +124,17 @@
new_lchan = lchan_alloc(conn_get_bts(conn), chan_type, 0);
if (!new_lchan) {
- LOGP(DMSC, LOGL_NOTICE, "No free channel.\n");
+ LOGP(DMSC, LOGL_NOTICE, "%s No free channel for %s\n",
+ bsc_subscr_name(conn->bsub), gsm_lchant_name(chan_type));
return -1;
}
/* check if we are on TCH/F and requested TCH/H, but got TCH/F */
if (conn->lchan->type == new_lchan->type
&& chan_type != new_lchan->type) {
- LOGP(DHO, LOGL_NOTICE, "%s -> %s Will not re-assign to identical channel type,"
- " %s was requested\n",
- gsm_lchan_name(conn->lchan), gsm_lchan_name(new_lchan),
- gsm_lchant_name(chan_type));
+ LOGPLCHAN(conn->lchan, DHO, LOGL_NOTICE,
+ "-> %s Will not re-assign to identical channel type, %s was requested\n",
+ gsm_lchan_name(new_lchan), gsm_lchant_name(chan_type));
lchan_free(new_lchan);
return -1;
}
@@ -148,7 +155,7 @@
handle_mr_config(conn, new_lchan, full_rate);
if (rsl_chan_activate_lchan(new_lchan, 0x1, 0) < 0) {
- LOGP(DHO, LOGL_ERROR, "could not activate channel\n");
+ LOGPLCHAN(new_lchan, DHO, LOGL_ERROR, "could not activate channel\n");
lchan_free(new_lchan);
return -1;
}
@@ -219,7 +226,8 @@
if (!conn->lchan) {
LOGP(DMSC, LOGL_ERROR,
- "Called submit dtap without an lchan.\n");
+ "%s Called submit dtap without an lchan.\n",
+ bsc_subscr_name(conn->bsub));
msgb_free(msg);
return -1;
}
@@ -316,11 +324,9 @@
if (chan_mode == GSM48_CMODE_SPEECH_AMR)
handle_mr_config(conn, conn->lchan, full_rate);
- LOGP(DMSC, LOGL_NOTICE,
- "Sending %s ChanModify for speech: %s on channel %s\n",
- gsm_lchan_name(conn->lchan),
- get_value_string(gsm48_chan_mode_names, chan_mode),
- get_value_string(gsm_chan_t_names, conn->lchan->type));
+ LOGPLCHAN(conn->lchan, DMSC, LOGL_NOTICE,
+ "Sending ChanModify for speech: %s\n",
+ get_value_string(gsm48_chan_mode_names, chan_mode));
gsm48_lchan_modify(conn->lchan, chan_mode);
}
@@ -348,8 +354,8 @@
struct lchan_signal_data sig;
struct gsm48_hdr *gh = msgb_l3(msg);
- DEBUGP(DRR, "ASSIGNMENT COMPLETE cause = %s\n",
- rr_cause_name(gh->data[0]));
+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG, "ASSIGNMENT COMPLETE cause = %s\n",
+ rr_cause_name(gh->data[0]));
sig.lchan = msg->lchan;
sig.mr = NULL;
@@ -363,14 +369,15 @@
}
if (conn->secondary_lchan != msg->lchan) {
- LOGP(DMSC, LOGL_ERROR, "Assignment Compl should occur on second lchan.\n");
+ LOGPLCHAN(msg->lchan, DMSC, LOGL_ERROR,
+ "Assignment Compl should occur on second lchan.\n");
return;
}
gh = msgb_l3(msg);
if (msgb_l3len(msg) - sizeof(*gh) != 1) {
- LOGP(DMSC, LOGL_ERROR, "Assignment Compl invalid: %zu\n",
- msgb_l3len(msg) - sizeof(*gh));
+ LOGPLCHAN(msg->lchan, DMSC, LOGL_ERROR, "Assignment Compl invalid: %zu\n",
+ msgb_l3len(msg) - sizeof(*gh));
return;
}
@@ -401,8 +408,8 @@
struct lchan_signal_data sig;
struct gsm48_hdr *gh = msgb_l3(msg);
- DEBUGP(DRR, "ASSIGNMENT FAILED cause = %s\n",
- rr_cause_name(gh->data[0]));
+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG, "ASSIGNMENT FAILED cause = %s\n",
+ rr_cause_name(gh->data[0]));
sig.lchan = msg->lchan;
sig.mr = NULL;
@@ -416,7 +423,8 @@
}
if (conn->lchan != msg->lchan) {
- LOGP(DMSC, LOGL_ERROR, "Assignment failure should occur on primary lchan.\n");
+ LOGPLCHAN(msg->lchan, DMSC, LOGL_ERROR,
+ "Assignment failure should occur on primary lchan.\n");
return;
}
@@ -432,8 +440,8 @@
gh = msgb_l3(msg);
if (msgb_l3len(msg) - sizeof(*gh) != 1) {
- LOGP(DMSC, LOGL_ERROR, "assignment failure unhandled: %zu\n",
- msgb_l3len(msg) - sizeof(*gh));
+ LOGPLCHAN(conn->lchan, DMSC, LOGL_ERROR, "assignment failure unhandled: %zu\n",
+ msgb_l3len(msg) - sizeof(*gh));
rr_failure = NULL;
} else {
rr_failure = &gh->data[0];
@@ -453,7 +461,7 @@
uint8_t cm2_len, cm3_len = 0;
uint8_t *cm2, *cm3 = NULL;
- DEBUGP(DRR, "CLASSMARK CHANGE ");
+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG, "CLASSMARK CHANGE ");
/* classmark 2 */
cm2_len = gh->data[0];
@@ -488,8 +496,8 @@
struct lchan_signal_data sig;
struct gsm48_hdr *gh = msgb_l3(msg);
- DEBUGP(DRR, "HANDOVER COMPLETE cause = %s\n",
- rr_cause_name(gh->data[0]));
+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG,
+ "HANDOVER COMPLETE cause = %s\n", rr_cause_name(gh->data[0]));
sig.lchan = msg->lchan;
sig.mr = NULL;
@@ -506,8 +514,12 @@
struct lchan_signal_data sig;
struct gsm48_hdr *gh = msgb_l3(msg);
- DEBUGP(DRR, "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));
- DEBUGP(DHO, "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));
+ /* Log on both RR and HO categories: it is an RR message, but is still quite important when
+ * filtering on HO. */
+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG,
+ "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));
+ LOGPLCHAN(msg->lchan, DHO, LOGL_DEBUG,
+ "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));
sig.lchan = msg->lchan;
sig.mr = NULL;
@@ -529,7 +541,8 @@
int rc;
if (msgb_l3len(msg) < sizeof(*gh)) {
- LOGP(DMSC, LOGL_ERROR, "Message too short for a GSM48 header.\n");
+ LOGP(DMSC, LOGL_ERROR, "(%s) Message too short for a GSM48 header.\n",
+ bsc_subscr_name(conn->bsub));
return;
}
@@ -547,19 +560,20 @@
case GSM48_PDISC_RR:
switch (msg_type) {
case GSM48_MT_RR_GPRS_SUSP_REQ:
- DEBUGP(DRR, "%s\n",
- gsm48_rr_msg_name(GSM48_MT_RR_GPRS_SUSP_REQ));
+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG,
+ "%s\n", gsm48_rr_msg_name(GSM48_MT_RR_GPRS_SUSP_REQ));
break;
case GSM48_MT_RR_STATUS:
- LOGP(DRR, LOGL_NOTICE, "%s (cause: %s)\n",
- gsm48_rr_msg_name(GSM48_MT_RR_STATUS),
- rr_cause_name(gh->data[0]));
+ LOGPLCHAN(msg->lchan, DRR, LOGL_NOTICE,
+ "%s (cause: %s)\n", gsm48_rr_msg_name(GSM48_MT_RR_STATUS),
+ rr_cause_name(gh->data[0]));
break;
case GSM48_MT_RR_MEAS_REP:
/* This shouldn't actually end up here, as RSL treats
* L3 Info of 08.58 MEASUREMENT REPORT different by calling
* directly into gsm48_parse_meas_rep */
- LOGP(DMEAS, LOGL_ERROR, "DIRECT GSM48 MEASUREMENT REPORT ?!? ");
+ LOGPLCHAN(msg->lchan, DMEAS, LOGL_ERROR,
+ "DIRECT GSM48 MEASUREMENT REPORT ?!?\n");
gsm48_tx_rr_status(conn, GSM48_RR_CAUSE_MSG_TYPE_N_COMPAT);
break;
case GSM48_MT_RR_HANDO_COMPL:
@@ -601,9 +615,8 @@
break;
default:
/* Drop unknown RR message */
- LOGP(DRR, LOGL_NOTICE,
- "%s Dropping %s 04.08 RR message\n",
- gsm_lchan_name(conn->lchan), gsm48_rr_msg_name(msg_type));
+ LOGPLCHAN(msg->lchan, DRR, LOGL_NOTICE,
+ "Dropping %s 04.08 RR message\n", gsm48_rr_msg_name(msg_type));
gsm48_tx_rr_status(conn, GSM48_RR_CAUSE_MSG_TYPE_N);
break;
}
@@ -624,8 +637,7 @@
lchan = msg->lchan;
if (lchan->state != LCHAN_S_ACTIVE) {
- LOGP(DRSL, LOGL_INFO, "Got data in non active state(%s), "
- "discarding.\n", gsm_lchans_name(lchan->state));
+ LOGPLCHAN(msg->lchan, DRSL, LOGL_INFO, "Got data in non active state, discarding.\n");
return -1;
}
@@ -660,12 +672,14 @@
const uint8_t *key, int len, int include_imeisv)
{
if (cipher > 0 && key == NULL) {
- LOGP(DRSL, LOGL_ERROR, "Need to have an encryption key.\n");
+ LOGP(DRSL, LOGL_ERROR, "%s: Need to have an encryption key.\n",
+ bsc_subscr_name(conn->bsub));
return -1;
}
if (len > MAX_A5_KEY_LEN) {
- LOGP(DRSL, LOGL_ERROR, "The key is too long: %d\n", len);
+ LOGP(DRSL, LOGL_ERROR, "%s: The key is too long: %d\n",
+ bsc_subscr_name(conn->bsub), len);
return -1;
}
@@ -807,7 +821,7 @@
if (conn->secondary_lchan != lchan)
return;
- LOGP(DMSC, LOGL_NOTICE, "Sending assignment on chan: %p\n", lchan);
+ LOGPLCHAN(lchan, DMSC, LOGL_NOTICE, "Sending RR Assignment\n");
gsm48_send_rr_ass_cmd(conn->lchan, lchan, lchan->ms_power);
}
@@ -817,7 +831,7 @@
if (conn->secondary_lchan != lchan)
return;
- LOGP(DMSC, LOGL_ERROR, "Channel activation failed. Waiting for timeout now\n");
+ LOGPLCHAN(lchan, DMSC, LOGL_ERROR, "Channel activation failed. Waiting for timeout now\n");
conn->secondary_lchan->conn = NULL;
conn->secondary_lchan = NULL;
}
--
To view, visit https://gerrit.osmocom.org/7996
To unsubscribe, visit https://gerrit.osmocom.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: If469defcc6fe8950dac5df61db3f39d297893318
Gerrit-PatchSet: 1
Gerrit-Project: osmo-bsc
Gerrit-Branch: master
Gerrit-Owner: Neels Hofmeyr <nhofmeyr at sysmocom.de>