<p>Harald Welte <strong>merged</strong> this change.</p><p><a href="https://gerrit.osmocom.org/7996">View Change</a></p><div style="white-space:pre-wrap">Approvals:
Harald Welte: Looks good to me, approved
Jenkins Builder: Verified
</div><pre style="font-family: monospace,monospace; white-space: pre-wrap;">bsc_api.c: actually log with context<br><br>bsc_api.c notoriously lacks log context. Provide gsm_lchan_name() and/or<br>bsc_subscr_name() in roughly a million instances, using new LOGPLCHAN macro.<br><br>Add LOGPLCHAN() to gsm_data.h, to encourage use of it in other .c files.<br><br>Change-Id: If469defcc6fe8950dac5df61db3f39d297893318<br>---<br>M include/osmocom/bsc/gsm_data.h<br>M src/libbsc/bsc_api.c<br>2 files changed, 58 insertions(+), 43 deletions(-)<br><br></pre><pre style="font-family: monospace,monospace; white-space: pre-wrap;"><span>diff --git a/include/osmocom/bsc/gsm_data.h b/include/osmocom/bsc/gsm_data.h</span><br><span>index 6f854d8..da5e87f 100644</span><br><span>--- a/include/osmocom/bsc/gsm_data.h</span><br><span>+++ b/include/osmocom/bsc/gsm_data.h</span><br><span>@@ -366,6 +366,14 @@</span><br><span> uint8_t key[MAX_A5_KEY_LEN];</span><br><span> };</span><br><span> </span><br><span style="color: hsl(120, 100%, 40%);">+#define LOGPLCHAN(lchan, ss, level, fmt, args...) \</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(ss, level, "%s (ss=%d,%s) (%s) " fmt, \</span><br><span style="color: hsl(120, 100%, 40%);">+ lchan ? gsm_ts_and_pchan_name(lchan->ts) : "-", \</span><br><span style="color: hsl(120, 100%, 40%);">+ lchan ? lchan->nr : 0, \</span><br><span style="color: hsl(120, 100%, 40%);">+ lchan ? gsm_lchant_name(lchan->type) : "-", \</span><br><span style="color: hsl(120, 100%, 40%);">+ bsc_subscr_name(lchan && lchan->conn ? lchan->conn->bsub : NULL), \</span><br><span style="color: hsl(120, 100%, 40%);">+ ## args)</span><br><span style="color: hsl(120, 100%, 40%);">+</span><br><span> struct gsm_lchan {</span><br><span> /* The TS that we're part of */</span><br><span> struct gsm_bts_trx_ts *ts;</span><br><span>diff --git a/src/libbsc/bsc_api.c b/src/libbsc/bsc_api.c</span><br><span>index 13fe099..71cc0f0 100644</span><br><span>--- a/src/libbsc/bsc_api.c</span><br><span>+++ b/src/libbsc/bsc_api.c</span><br><span>@@ -117,17 +117,17 @@</span><br><span> new_lchan = lchan_alloc(conn_get_bts(conn), chan_type, 0);</span><br><span> </span><br><span> if (!new_lchan) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_NOTICE, "No free channel.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DMSC, LOGL_NOTICE, "%s No free channel for %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ bsc_subscr_name(conn->bsub), gsm_lchant_name(chan_type));</span><br><span> return -1;</span><br><span> }</span><br><span> </span><br><span> /* check if we are on TCH/F and requested TCH/H, but got TCH/F */</span><br><span> if (conn->lchan->type == new_lchan->type</span><br><span> && chan_type != new_lchan->type) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DHO, LOGL_NOTICE, "%s -> %s Will not re-assign to identical channel type,"</span><br><span style="color: hsl(0, 100%, 40%);">- " %s was requested\n",</span><br><span style="color: hsl(0, 100%, 40%);">- gsm_lchan_name(conn->lchan), gsm_lchan_name(new_lchan),</span><br><span style="color: hsl(0, 100%, 40%);">- gsm_lchant_name(chan_type));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(conn->lchan, DHO, LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ "-> %s Will not re-assign to identical channel type, %s was requested\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ gsm_lchan_name(new_lchan), gsm_lchant_name(chan_type));</span><br><span> lchan_free(new_lchan);</span><br><span> return -1;</span><br><span> }</span><br><span>@@ -148,7 +148,7 @@</span><br><span> handle_mr_config(conn, new_lchan, full_rate);</span><br><span> </span><br><span> if (rsl_chan_activate_lchan(new_lchan, 0x1, 0) < 0) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DHO, LOGL_ERROR, "could not activate channel\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(new_lchan, DHO, LOGL_ERROR, "could not activate channel\n");</span><br><span> lchan_free(new_lchan);</span><br><span> return -1;</span><br><span> }</span><br><span>@@ -217,7 +217,8 @@</span><br><span> </span><br><span> if (!conn->lchan) {</span><br><span> LOGP(DMSC, LOGL_ERROR,</span><br><span style="color: hsl(0, 100%, 40%);">- "Called submit dtap without an lchan.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ "%s Called submit dtap without an lchan.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ bsc_subscr_name(conn->bsub));</span><br><span> msgb_free(msg);</span><br><span> return -1;</span><br><span> }</span><br><span>@@ -320,11 +321,9 @@</span><br><span> if (chan_mode == GSM48_CMODE_SPEECH_AMR)</span><br><span> handle_mr_config(conn, conn->lchan, full_rate);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_NOTICE,</span><br><span style="color: hsl(0, 100%, 40%);">- "Sending %s ChanModify for speech: %s on channel %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- gsm_lchan_name(conn->lchan),</span><br><span style="color: hsl(0, 100%, 40%);">- get_value_string(gsm48_chan_mode_names, chan_mode),</span><br><span style="color: hsl(0, 100%, 40%);">- get_value_string(gsm_chan_t_names, conn->lchan->type));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(conn->lchan, DMSC, LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ "Sending ChanModify for speech: %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ get_value_string(gsm48_chan_mode_names, chan_mode));</span><br><span> gsm48_lchan_modify(conn->lchan, chan_mode);</span><br><span> }</span><br><span> </span><br><span>@@ -352,8 +351,8 @@</span><br><span> struct lchan_signal_data sig;</span><br><span> struct gsm48_hdr *gh = msgb_l3(msg);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DRR, "ASSIGNMENT COMPLETE cause = %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG, "ASSIGNMENT COMPLETE cause = %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ rr_cause_name(gh->data[0]));</span><br><span> </span><br><span> sig.lchan = msg->lchan;</span><br><span> sig.mr = NULL;</span><br><span>@@ -367,14 +366,15 @@</span><br><span> }</span><br><span> </span><br><span> if (conn->secondary_lchan != msg->lchan) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_ERROR, "Assignment Compl should occur on second lchan.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DMSC, LOGL_ERROR,</span><br><span style="color: hsl(120, 100%, 40%);">+ "Assignment Compl should occur on second lchan.\n");</span><br><span> return;</span><br><span> }</span><br><span> </span><br><span> gh = msgb_l3(msg);</span><br><span> if (msgb_l3len(msg) - sizeof(*gh) != 1) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_ERROR, "Assignment Compl invalid: %zu\n",</span><br><span style="color: hsl(0, 100%, 40%);">- msgb_l3len(msg) - sizeof(*gh));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DMSC, LOGL_ERROR, "Assignment Compl invalid: %zu\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ msgb_l3len(msg) - sizeof(*gh));</span><br><span> return;</span><br><span> }</span><br><span> </span><br><span>@@ -405,8 +405,8 @@</span><br><span> struct lchan_signal_data sig;</span><br><span> struct gsm48_hdr *gh = msgb_l3(msg);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DRR, "ASSIGNMENT FAILED cause = %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG, "ASSIGNMENT FAILED cause = %s\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ rr_cause_name(gh->data[0]));</span><br><span> </span><br><span> sig.lchan = msg->lchan;</span><br><span> sig.mr = NULL;</span><br><span>@@ -420,7 +420,8 @@</span><br><span> }</span><br><span> </span><br><span> if (conn->lchan != msg->lchan) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_ERROR, "Assignment failure should occur on primary lchan.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DMSC, LOGL_ERROR,</span><br><span style="color: hsl(120, 100%, 40%);">+ "Assignment failure should occur on primary lchan.\n");</span><br><span> return;</span><br><span> }</span><br><span> </span><br><span>@@ -436,8 +437,8 @@</span><br><span> </span><br><span> gh = msgb_l3(msg);</span><br><span> if (msgb_l3len(msg) - sizeof(*gh) != 1) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_ERROR, "assignment failure unhandled: %zu\n",</span><br><span style="color: hsl(0, 100%, 40%);">- msgb_l3len(msg) - sizeof(*gh));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(conn->lchan, DMSC, LOGL_ERROR, "assignment failure unhandled: %zu\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ msgb_l3len(msg) - sizeof(*gh));</span><br><span> rr_failure = NULL;</span><br><span> } else {</span><br><span> rr_failure = &gh->data[0];</span><br><span>@@ -457,7 +458,7 @@</span><br><span> uint8_t cm2_len, cm3_len = 0;</span><br><span> uint8_t *cm2, *cm3 = NULL;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DRR, "CLASSMARK CHANGE ");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG, "CLASSMARK CHANGE ");</span><br><span> </span><br><span> /* classmark 2 */</span><br><span> cm2_len = gh->data[0];</span><br><span>@@ -492,8 +493,8 @@</span><br><span> struct lchan_signal_data sig;</span><br><span> struct gsm48_hdr *gh = msgb_l3(msg);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DRR, "HANDOVER COMPLETE cause = %s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG,</span><br><span style="color: hsl(120, 100%, 40%);">+ "HANDOVER COMPLETE cause = %s\n", rr_cause_name(gh->data[0]));</span><br><span> </span><br><span> sig.lchan = msg->lchan;</span><br><span> sig.mr = NULL;</span><br><span>@@ -510,8 +511,12 @@</span><br><span> struct lchan_signal_data sig;</span><br><span> struct gsm48_hdr *gh = msgb_l3(msg);</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DRR, "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DHO, "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ /* Log on both RR and HO categories: it is an RR message, but is still quite important when</span><br><span style="color: hsl(120, 100%, 40%);">+ * filtering on HO. */</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG,</span><br><span style="color: hsl(120, 100%, 40%);">+ "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DHO, LOGL_DEBUG,</span><br><span style="color: hsl(120, 100%, 40%);">+ "HANDOVER FAILED cause = %s\n", rr_cause_name(gh->data[0]));</span><br><span> </span><br><span> sig.lchan = msg->lchan;</span><br><span> sig.mr = NULL;</span><br><span>@@ -533,7 +538,8 @@</span><br><span> int rc;</span><br><span> </span><br><span> if (msgb_l3len(msg) < sizeof(*gh)) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_ERROR, "Message too short for a GSM48 header.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DMSC, LOGL_ERROR, "(%s) Message too short for a GSM48 header.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ bsc_subscr_name(conn->bsub));</span><br><span> return;</span><br><span> }</span><br><span> </span><br><span>@@ -551,19 +557,20 @@</span><br><span> case GSM48_PDISC_RR:</span><br><span> switch (msg_type) {</span><br><span> case GSM48_MT_RR_GPRS_SUSP_REQ:</span><br><span style="color: hsl(0, 100%, 40%);">- DEBUGP(DRR, "%s\n",</span><br><span style="color: hsl(0, 100%, 40%);">- gsm48_rr_msg_name(GSM48_MT_RR_GPRS_SUSP_REQ));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_DEBUG,</span><br><span style="color: hsl(120, 100%, 40%);">+ "%s\n", gsm48_rr_msg_name(GSM48_MT_RR_GPRS_SUSP_REQ));</span><br><span> break;</span><br><span> case GSM48_MT_RR_STATUS:</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DRR, LOGL_NOTICE, "%s (cause: %s)\n",</span><br><span style="color: hsl(0, 100%, 40%);">- gsm48_rr_msg_name(GSM48_MT_RR_STATUS),</span><br><span style="color: hsl(0, 100%, 40%);">- rr_cause_name(gh->data[0]));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ "%s (cause: %s)\n", gsm48_rr_msg_name(GSM48_MT_RR_STATUS),</span><br><span style="color: hsl(120, 100%, 40%);">+ rr_cause_name(gh->data[0]));</span><br><span> break;</span><br><span> case GSM48_MT_RR_MEAS_REP:</span><br><span> /* This shouldn't actually end up here, as RSL treats</span><br><span> * L3 Info of 08.58 MEASUREMENT REPORT different by calling</span><br><span> * directly into gsm48_parse_meas_rep */</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMEAS, LOGL_ERROR, "DIRECT GSM48 MEASUREMENT REPORT ?!? ");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DMEAS, LOGL_ERROR,</span><br><span style="color: hsl(120, 100%, 40%);">+ "DIRECT GSM48 MEASUREMENT REPORT ?!?\n");</span><br><span> gsm48_tx_rr_status(conn, GSM48_RR_CAUSE_MSG_TYPE_N_COMPAT);</span><br><span> break;</span><br><span> case GSM48_MT_RR_HANDO_COMPL:</span><br><span>@@ -605,9 +612,8 @@</span><br><span> break;</span><br><span> default:</span><br><span> /* Drop unknown RR message */</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DRR, LOGL_NOTICE,</span><br><span style="color: hsl(0, 100%, 40%);">- "%s Dropping %s 04.08 RR message\n",</span><br><span style="color: hsl(0, 100%, 40%);">- gsm_lchan_name(conn->lchan), gsm48_rr_msg_name(msg_type));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRR, LOGL_NOTICE,</span><br><span style="color: hsl(120, 100%, 40%);">+ "Dropping %s 04.08 RR message\n", gsm48_rr_msg_name(msg_type));</span><br><span> gsm48_tx_rr_status(conn, GSM48_RR_CAUSE_MSG_TYPE_N);</span><br><span> break;</span><br><span> }</span><br><span>@@ -628,8 +634,7 @@</span><br><span> </span><br><span> lchan = msg->lchan;</span><br><span> if (lchan->state != LCHAN_S_ACTIVE) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DRSL, LOGL_INFO, "Got data in non active state(%s), "</span><br><span style="color: hsl(0, 100%, 40%);">- "discarding.\n", gsm_lchans_name(lchan->state));</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(msg->lchan, DRSL, LOGL_INFO, "Got data in non active state, discarding.\n");</span><br><span> return -1;</span><br><span> }</span><br><span> </span><br><span>@@ -664,12 +669,14 @@</span><br><span> const uint8_t *key, int len, int include_imeisv)</span><br><span> {</span><br><span> if (cipher > 0 && key == NULL) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DRSL, LOGL_ERROR, "Need to have an encryption key.\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DRSL, LOGL_ERROR, "%s: Need to have an encryption key.\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ bsc_subscr_name(conn->bsub));</span><br><span> return -1;</span><br><span> }</span><br><span> </span><br><span> if (len > MAX_A5_KEY_LEN) {</span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DRSL, LOGL_ERROR, "The key is too long: %d\n", len);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGP(DRSL, LOGL_ERROR, "%s: The key is too long: %d\n",</span><br><span style="color: hsl(120, 100%, 40%);">+ bsc_subscr_name(conn->bsub), len);</span><br><span> return -1;</span><br><span> }</span><br><span> </span><br><span>@@ -811,7 +818,7 @@</span><br><span> if (conn->secondary_lchan != lchan)</span><br><span> return;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_NOTICE, "Sending assignment on chan: %p\n", lchan);</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(lchan, DMSC, LOGL_NOTICE, "Sending RR Assignment\n");</span><br><span> gsm48_send_rr_ass_cmd(conn->lchan, lchan, lchan->ms_power);</span><br><span> }</span><br><span> </span><br><span>@@ -821,7 +828,7 @@</span><br><span> if (conn->secondary_lchan != lchan)</span><br><span> return;</span><br><span> </span><br><span style="color: hsl(0, 100%, 40%);">- LOGP(DMSC, LOGL_ERROR, "Channel activation failed. Waiting for timeout now\n");</span><br><span style="color: hsl(120, 100%, 40%);">+ LOGPLCHAN(lchan, DMSC, LOGL_ERROR, "Channel activation failed. Waiting for timeout now\n");</span><br><span> conn->secondary_lchan->conn = NULL;</span><br><span> conn->secondary_lchan = NULL;</span><br><span> }</span><br><span></span><br></pre><p>To view, visit <a href="https://gerrit.osmocom.org/7996">change 7996</a>. To unsubscribe, or for help writing mail filters, visit <a href="https://gerrit.osmocom.org/settings">settings</a>.</p><div itemscope itemtype="http://schema.org/EmailMessage"><div itemscope itemprop="action" itemtype="http://schema.org/ViewAction"><link itemprop="url" href="https://gerrit.osmocom.org/7996"/><meta itemprop="name" content="View Change"/></div></div>
<div style="display:none"> Gerrit-Project: osmo-bsc </div>
<div style="display:none"> Gerrit-Branch: master </div>
<div style="display:none"> Gerrit-MessageType: merged </div>
<div style="display:none"> Gerrit-Change-Id: If469defcc6fe8950dac5df61db3f39d297893318 </div>
<div style="display:none"> Gerrit-Change-Number: 7996 </div>
<div style="display:none"> Gerrit-PatchSet: 3 </div>
<div style="display:none"> Gerrit-Owner: Neels Hofmeyr <nhofmeyr@sysmocom.de> </div>
<div style="display:none"> Gerrit-Reviewer: Harald Welte <laforge@gnumonks.org> </div>
<div style="display:none"> Gerrit-Reviewer: Jenkins Builder </div>
<div style="display:none"> Gerrit-Reviewer: Neels Hofmeyr <nhofmeyr@sysmocom.de> </div>