logging: introduce LOG_BTS and LOG_TRX and use it everywhere

It's quite ugly to have manual "bts=%d" printf-statements all over
the BSC code.  Let's change this to use shared logging helper functions
all over the place, whenever we need to log something related to one
BTS or one TRX.

This can also help us as the first step to later add alternative logging
of BTS identities, e.g. by printing the Cell Global Identifier or
LAC+CI, or even a human-readable/vty-defined 'name' of the BTS, rather
than its numeric bts number.  With this change in place, we can
introduce such changes at a single location in the code.

Change-Id: I4a7814d164384eecfb6913c31802cf2faead6e6c

9 files changed, 89 insertions, 105 deletions

diff --git a/include/osmocom/bsc/debug.h b/include/osmocom/bsc/debug.h
index e78ba59a8..326012185 100644
--- a/include/osmocom/bsc/debug.h
+++ b/include/osmocom/bsc/debug.h
@@ -29,3 +29,9 @@ enum {
 	DAS,
 	Debug_LastEntry,
 };
+
+#define LOG_BTS(bts, subsys, level, fmt, args...) \
+	LOGP(subsys, level, "(bts=%d) " fmt, (bts)->nr, ## args)
+
+#define LOG_TRX(trx, subsys, level, fmt, args...) \
+	LOGP(subsys, level, "(bts=%d,trx=%d) " fmt, (trx)->bts->nr, (trx)->nr, ## args)
diff --git a/src/osmo-bsc/abis_nm.c b/src/osmo-bsc/abis_nm.c
index bff6c1258..7d059b5d1 100644
--- a/src/osmo-bsc/abis_nm.c
+++ b/src/osmo-bsc/abis_nm.c
@@ -1713,7 +1713,7 @@ int abis_nm_get_attr(struct gsm_bts *bts, uint8_t obj_class, uint8_t bts_nr, uin
 		return -EINVAL;
 	}
 
-	DEBUGP(DNM, "Get Attr (bts=%u,trx=%u)\n", bts->nr, trx_nr);
+	LOG_BTS(bts, DNM, LOGL_DEBUG, "Get Attr (trx=%u)\n", trx_nr);
 
 	msg = nm_msgb_alloc();
 	oh = (struct abis_om_hdr *) msgb_put(msg, ABIS_OM_FOM_HDR_SIZE);
@@ -1731,7 +1731,7 @@ int abis_nm_set_bts_attr(struct gsm_bts *bts, uint8_t *attr, int attr_len)
 	struct msgb *msg = nm_msgb_alloc();
 	uint8_t *cur;
 
-	DEBUGP(DNM, "Set BTS Attr (bts=%u)\n", bts->nr);
+	LOG_BTS(bts, DNM, LOGL_DEBUG, "Set BTS Attr\n");
 
 	oh = (struct abis_om_hdr *) msgb_put(msg, ABIS_OM_FOM_HDR_SIZE);
 	fill_om_fom_hdr(oh, attr_len, NM_MT_SET_BTS_ATTR, NM_OC_BTS, bts->bts_nr, 0xff, 0xff);
@@ -1748,7 +1748,7 @@ int abis_nm_set_radio_attr(struct gsm_bts_trx *trx, uint8_t *attr, int attr_len)
 	struct msgb *msg = nm_msgb_alloc();
 	uint8_t *cur;
 
-	DEBUGP(DNM, "Set TRX Attr (bts=%u,trx=%u)\n", trx->bts->nr, trx->nr);
+	LOG_TRX(trx, DNM, LOGL_DEBUG, "Set TRX Attr\n");
 
 	oh = (struct abis_om_hdr *) msgb_put(msg, ABIS_OM_FOM_HDR_SIZE);
 	fill_om_fom_hdr(oh, attr_len, NM_MT_SET_RADIO_ATTR, NM_OC_RADIO_CARRIER,
@@ -2849,7 +2849,7 @@ static void rsl_connect_timeout(void *data)
 	struct gsm_bts_trx *trx = data;
 	struct ipacc_ack_signal_data signal;
 
-	LOGP(DRSL, LOGL_NOTICE, "(bts=%u,trx=%u) RSL connection request timed out\n", trx->bts->nr, trx->nr);
+	LOG_TRX(trx, DRSL, LOGL_NOTICE, "RSL connection request timed out\n");
 
 	/* Fake an RSL CONECT NACK message from the BTS. */
 	signal.trx = trx;
@@ -2880,8 +2880,8 @@ int abis_nm_ipaccess_rsl_connect(struct gsm_bts_trx *trx,
 	if (ip == 0)
 		attr_len -= 5;
 
-	LOGP(DNM, LOGL_INFO, "(bts=%u,trx=%u) IPA RSL CONNECT IP=%s PORT=%u STREAM=0x%02x\n",
-		trx->bts->nr, trx->nr, inet_ntoa(ia), port, stream);
+	LOG_TRX(trx, DNM, LOGL_INFO, "IPA RSL CONNECT IP=%s PORT=%u STREAM=0x%02x\n",
+		inet_ntoa(ia), port, stream);
 
 	error = abis_nm_ipaccess_msg(trx->bts, NM_MT_IPACC_RSL_CONNECT,
 				     NM_OC_BASEB_TRANSC, trx->bts->bts_nr,
@@ -2935,8 +2935,7 @@ void gsm_trx_lock_rf(struct gsm_bts_trx *trx, bool locked, const char *reason)
 		return;
 	}
 
-	LOGP(DNM, LOGL_NOTICE, "(bts=%u,trx=%u) Requesting administrative state change %s -> %s [%s]\n",
-	     trx->bts->nr, trx->nr,
+	LOG_TRX(trx, DNM, LOGL_NOTICE, "Requesting administrative state change %s -> %s [%s]\n",
 	     get_value_string(abis_nm_adm_state_names, trx->mo.nm_state.administrative),
 	     get_value_string(abis_nm_adm_state_names, new_state), reason);
 
diff --git a/src/osmo-bsc/abis_rsl.c b/src/osmo-bsc/abis_rsl.c
index 9db2115e5..0b68d7c53 100644
--- a/src/osmo-bsc/abis_rsl.c
+++ b/src/osmo-bsc/abis_rsl.c
@@ -1357,10 +1357,8 @@ static int rsl_rx_chan_rqd(struct msgb *msg)
 
 	/* Determine channel request cause code */
 	chreq_reason = get_reason_by_chreq(rqd_ref->ra, bts->network->neci);
-	LOGP(DRSL, LOGL_NOTICE, "(bts=%d) CHAN RQD: reason: %s (ra=0x%02x, neci=0x%02x, chreq_reason=0x%02x)\n",
-	     msg->lchan->ts->trx->bts->nr,
-	     get_value_string(gsm_chreq_descs, chreq_reason),
-	     rqd_ref->ra, bts->network->neci, chreq_reason);
+	LOG_BTS(bts, DRSL, LOGL_NOTICE, "CHAN RQD: reason: %s (ra=0x%02x, neci=0x%02x, chreq_reason=0x%02x)\n",
+		get_value_string(gsm_chreq_descs, chreq_reason), rqd_ref->ra, bts->network->neci, chreq_reason);
 
 	/* Handle PDCH related rach requests (in case of BSC-co-located-PCU */
 	if (chreq_reason == GSM_CHREQ_REASON_PDCH)
@@ -1381,24 +1379,18 @@ static int rsl_rx_chan_rqd(struct msgb *msg)
 	 */
 	lchan = lchan_select_by_type(bts, GSM_LCHAN_SDCCH);
 	if (!lchan) {
-		LOGP(DRSL, LOGL_NOTICE, "(bts=%d) CHAN RQD: no resources for %s "
-			"0x%x, retrying with %s\n",
-			msg->lchan->ts->trx->bts->nr,
-			gsm_lchant_name(GSM_LCHAN_SDCCH), rqd_ref->ra,
-			gsm_lchant_name(GSM_LCHAN_TCH_H));
+		LOG_BTS(bts, DRSL, LOGL_NOTICE, "CHAN RQD: no resources for %s 0x%x, retrying with %s\n",
+			gsm_lchant_name(GSM_LCHAN_SDCCH), rqd_ref->ra, gsm_lchant_name(GSM_LCHAN_TCH_H));
 		lchan = lchan_select_by_type(bts, GSM_LCHAN_TCH_H);
 	}
 	if (!lchan) {
-		LOGP(DRSL, LOGL_NOTICE, "(bts=%d) CHAN RQD: no resources for %s "
-			"0x%x, retrying with %s\n",
-			msg->lchan->ts->trx->bts->nr,
-			gsm_lchant_name(GSM_LCHAN_SDCCH), rqd_ref->ra,
-			gsm_lchant_name(GSM_LCHAN_TCH_F));
+		LOG_BTS(bts, DRSL, LOGL_NOTICE, "CHAN RQD: no resources for %s 0x%x, retrying with %s\n",
+			gsm_lchant_name(GSM_LCHAN_SDCCH), rqd_ref->ra, gsm_lchant_name(GSM_LCHAN_TCH_F));
 		lchan = lchan_select_by_type(bts, GSM_LCHAN_TCH_F);
 	}
 	if (!lchan) {
-		LOGP(DRSL, LOGL_NOTICE, "(bts=%d) CHAN RQD: no resources for %s 0x%x\n",
-		     msg->lchan->ts->trx->bts->nr, gsm_lchant_name(lctype), rqd_ref->ra);
+		LOG_BTS(bts, DRSL, LOGL_NOTICE, "CHAN RQD: no resources for %s 0x%x\n",
+			gsm_lchant_name(lctype), rqd_ref->ra);
 		rate_ctr_inc(&bts->bts_ctrs->ctr[BTS_CTR_CHREQ_NO_CHANNEL]);
 		rsl_tx_imm_ass_rej(bts, rqd_ref);
 		return 0;
diff --git a/src/osmo-bsc/acc_ramp.c b/src/osmo-bsc/acc_ramp.c
index bc2e3fb73..b79c0c2ac 100644
--- a/src/osmo-bsc/acc_ramp.c
+++ b/src/osmo-bsc/acc_ramp.c
@@ -46,7 +46,8 @@ static void allow_one_acc(struct acc_ramp *acc_ramp, unsigned int acc)
 {
 	OSMO_ASSERT(acc <= 9);
 	if (acc_ramp->barred_accs & (1 << acc))
-		LOGP(DRSL, LOGL_NOTICE, "(bts=%d) ACC RAMP: allowing Access Control Class %u\n", acc_ramp->bts->nr, acc);
+		LOG_BTS(acc_ramp->bts, DRSL, LOGL_NOTICE,
+			"ACC RAMP: allowing Access Control Class %u\n", acc);
 	acc_ramp->barred_accs &= ~(1 << acc);
 }
 
@@ -54,7 +55,8 @@ static void barr_one_acc(struct acc_ramp *acc_ramp, unsigned int acc)
 {
 	OSMO_ASSERT(acc <= 9);
 	if ((acc_ramp->barred_accs & (1 << acc)) == 0)
-		LOGP(DRSL, LOGL_NOTICE, "(bts=%d) ACC RAMP: barring Access Control Class %u\n", acc_ramp->bts->nr, acc);
+		LOG_BTS(acc_ramp->bts, DRSL, LOGL_NOTICE,
+			"ACC RAMP: barring Access Control Class %u\n", acc);
 	acc_ramp->barred_accs |= (1 << acc);
 }
 
@@ -92,8 +94,9 @@ static unsigned int get_next_step_interval(struct acc_ramp *acc_ramp)
 	else if (acc_ramp->step_interval_sec > ACC_RAMP_STEP_INTERVAL_MAX)
 		acc_ramp->step_interval_sec = ACC_RAMP_STEP_INTERVAL_MAX;
 
-	LOGP(DRSL, LOGL_DEBUG, "(bts=%d) ACC RAMP: step interval set to %u seconds based on %u%% channel load average\n",
-	     bts->nr, acc_ramp->step_interval_sec, bts->chan_load_avg);
+	LOG_BTS(bts, DRSL, LOGL_DEBUG,
+		"ACC RAMP: step interval set to %u seconds based on %u%% channel load average\n",
+	        acc_ramp->step_interval_sec, bts->chan_load_avg);
 	return acc_ramp->step_interval_sec;
 }
 
@@ -156,12 +159,10 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 
 	trx = nsd->obj;
 
-	LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: administrative state %s -> %s\n",
-	    acc_ramp->bts->nr, trx->nr,
+	LOG_TRX(trx, DRSL, LOGL_DEBUG, "ACC RAMP: administrative state %s -> %s\n",
 	    get_value_string(abis_nm_adm_state_names, nsd->old_state->administrative),
 	    get_value_string(abis_nm_adm_state_names, nsd->new_state->administrative));
-	LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: operational state %s -> %s\n",
-	    acc_ramp->bts->nr, trx->nr,
+	LOG_TRX(trx, DRSL, LOGL_DEBUG, "ACC RAMP: operational state %s -> %s\n",
 	    abis_nm_opstate_name(nsd->old_state->operational),
 	    abis_nm_opstate_name(nsd->new_state->operational));
 
@@ -171,8 +172,8 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 
 	/* RSL must already be up. We cannot send RACH system information to the BTS otherwise. */
 	if (trx->rsl_link == NULL) {
-		LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: ignoring state change because RSL link is down\n",
-		     acc_ramp->bts->nr, trx->nr);
+		LOG_TRX(trx, DRSL, LOGL_DEBUG,
+			"ACC RAMP: ignoring state change because RSL link is down\n");
 		return 0;
 	}
 
@@ -188,10 +189,10 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 				if (nsd->new_state->operational == NM_OPSTATE_ENABLED)
 					trigger_ramping = true;
 				else
-					LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: ignoring state change "
-					     "because TRX is transitioning into operational state '%s'\n",
-					     acc_ramp->bts->nr, trx->nr,
-					     abis_nm_opstate_name(nsd->new_state->operational));
+					LOG_TRX(trx, DRSL, LOGL_DEBUG,
+						"ACC RAMP: ignoring state change because TRX is "
+						"transitioning into operational state '%s'\n",
+						abis_nm_opstate_name(nsd->new_state->operational));
 			} else {
 				/*
 				 * Operational state has not changed.
@@ -200,8 +201,8 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 				if (trx_is_usable(trx))
 					trigger_ramping = true;
 				else
-					LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: ignoring state change "
-					     "because TRX is not usable\n", acc_ramp->bts->nr, trx->nr);
+					LOG_TRX(trx, DRSL, LOGL_DEBUG, "ACC RAMP: ignoring state change "
+						"because TRX is not usable\n");
 			}
 			break;
 		case NM_STATE_LOCKED:
@@ -210,8 +211,8 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 			break;
 		case NM_STATE_NULL:
 		default:
-			LOGP(DRSL, LOGL_ERROR, "(bts=%d) ACC RAMP: unrecognized administrative state '0x%x' "
-			    "reported for TRX 0\n", acc_ramp->bts->nr, nsd->new_state->administrative);
+			LOG_TRX(trx, DRSL, LOGL_ERROR, "ACC RAMP: unrecognized administrative state '0x%x' "
+				"reported for TRX 0\n", nsd->new_state->administrative);
 			break;
 		}
 	}
@@ -226,10 +227,9 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 				if (nsd->new_state->administrative == NM_STATE_UNLOCKED)
 					trigger_ramping = true;
 				else
-					LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: ignoring state change "
-					     "because TRX is transitioning into administrative state '%s'\n",
-					     acc_ramp->bts->nr, trx->nr,
-					     get_value_string(abis_nm_adm_state_names, nsd->new_state->administrative));
+					LOG_TRX(trx, DRSL, LOGL_DEBUG, "ACC RAMP: ignoring state change "
+						"because TRX is transitioning into administrative state '%s'\n",
+						get_value_string(abis_nm_adm_state_names, nsd->new_state->administrative));
 			} else {
 				/*
 				 * Administrative state has not changed.
@@ -238,10 +238,9 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 				if (trx->mo.nm_state.administrative == NM_STATE_UNLOCKED)
 					trigger_ramping = true;
 				else
-					LOGP(DRSL, LOGL_DEBUG, "(bts=%d,trx=%d) ACC RAMP: ignoring state change "
-					     "because TRX is in administrative state '%s'\n",
-					     acc_ramp->bts->nr, trx->nr,
-					     get_value_string(abis_nm_adm_state_names, trx->mo.nm_state.administrative));
+					LOG_TRX(trx, DRSL, LOGL_DEBUG, "ACC RAMP: ignoring state change "
+						"because TRX is in administrative state '%s'\n",
+						get_value_string(abis_nm_adm_state_names, trx->mo.nm_state.administrative));
 			}
 			break;
 		case NM_OPSTATE_DISABLED:
@@ -249,8 +248,8 @@ static int acc_ramp_nm_sig_cb(unsigned int subsys, unsigned int signal, void *ha
 			break;
 		case NM_OPSTATE_NULL:
 		default:
-			LOGP(DRSL, LOGL_ERROR, "(bts=%d) ACC RAMP: unrecognized operational state '0x%x' "
-			     "reported for TRX 0\n", acc_ramp->bts->nr, nsd->new_state->administrative);
+			LOG_TRX(trx, DRSL, LOGL_ERROR, "ACC RAMP: unrecognized operational state '0x%x' "
+			     "reported for TRX 0\n", nsd->new_state->administrative);
 			break;
 		}
 	}
@@ -296,7 +295,7 @@ int acc_ramp_set_step_size(struct acc_ramp *acc_ramp, unsigned int step_size)
 		return -ERANGE;
 
 	acc_ramp->step_size = step_size;
-	LOGP(DRSL, LOGL_DEBUG, "(bts=%d) ACC RAMP: ramping step size set to %u\n", acc_ramp->bts->nr, step_size);
+	LOG_BTS(acc_ramp->bts, DRSL, LOGL_DEBUG, "ACC RAMP: ramping step size set to %u\n", step_size);
 	return 0;
 }
 
@@ -313,8 +312,8 @@ int acc_ramp_set_step_interval(struct acc_ramp *acc_ramp, unsigned int step_inte
 
 	acc_ramp->step_interval_sec = step_interval;
 	acc_ramp->step_interval_is_fixed = true;
-	LOGP(DRSL, LOGL_DEBUG, "(bts=%d) ACC RAMP: ramping step interval set to %u seconds\n",
-	     acc_ramp->bts->nr, step_interval);
+	LOG_BTS(acc_ramp->bts, DRSL, LOGL_DEBUG, "ACC RAMP: ramping step interval set to %u seconds\n",
+		step_interval);
 	return 0;
 }
 
@@ -326,8 +325,7 @@ int acc_ramp_set_step_interval(struct acc_ramp *acc_ramp, unsigned int step_inte
 void acc_ramp_set_step_interval_dynamic(struct acc_ramp *acc_ramp)
 {
 	acc_ramp->step_interval_is_fixed = false;
-	LOGP(DRSL, LOGL_DEBUG, "(bts=%d) ACC RAMP: ramping step interval set to 'dynamic'\n",
-	     acc_ramp->bts->nr);
+	LOG_BTS(acc_ramp->bts, DRSL, LOGL_DEBUG, "ACC RAMP: ramping step interval set to 'dynamic'\n");
 }
 
 /*!
diff --git a/src/osmo-bsc/bts_ipaccess_nanobts.c b/src/osmo-bsc/bts_ipaccess_nanobts.c
index 56103b6f2..a5e697be1 100644
--- a/src/osmo-bsc/bts_ipaccess_nanobts.c
+++ b/src/osmo-bsc/bts_ipaccess_nanobts.c
@@ -394,7 +394,7 @@ void ipaccess_drop_rsl(struct gsm_bts_trx *trx, const char *reason)
 	if (!trx->rsl_link)
 		return;
 
-	LOGP(DLINP, LOGL_NOTICE, "(bts=%d,trx=%d) Dropping RSL link: %s\n", trx->bts->nr, trx->nr, reason);
+	LOG_TRX(trx, DLINP, LOGL_NOTICE, "Dropping RSL link: %s\n", reason);
 	e1inp_sign_link_destroy(trx->rsl_link);
 	trx->rsl_link = NULL;
 
@@ -413,7 +413,7 @@ void ipaccess_drop_oml(struct gsm_bts *bts, const char *reason)
 	if (!bts->oml_link)
 		return;
 
-	LOGP(DLINP, LOGL_NOTICE, "(bts=%d) Dropping OML link: %s\n", bts->nr, reason);
+	LOG_BTS(bts, DLINP, LOGL_NOTICE, "Dropping OML link: %s\n", reason);
 	e1inp_sign_link_destroy(bts->oml_link);
 	bts->oml_link = NULL;
 	bts->uptime = 0;
@@ -459,7 +459,7 @@ static void ipaccess_drop_oml_deferred_cb(void *data)
 void ipaccess_drop_oml_deferred(struct gsm_bts *bts)
 {
 	if (!osmo_timer_pending(&bts->oml_drop_link_timer) && bts->oml_link) {
-		LOGP(DLINP, LOGL_NOTICE, "(bts=%d) Deferring Drop of OML link.\n", bts->nr);
+		LOG_BTS(bts, DLINP, LOGL_NOTICE, "Deferring Drop of OML link.\n");
 		osmo_timer_setup(&bts->oml_drop_link_timer, ipaccess_drop_oml_deferred_cb, bts);
 		osmo_timer_schedule(&bts->oml_drop_link_timer, 0, 0);
 	}
diff --git a/src/osmo-bsc/chan_alloc.c b/src/osmo-bsc/chan_alloc.c
index 7f0aa31aa..669eb8edb 100644
--- a/src/osmo-bsc/chan_alloc.c
+++ b/src/osmo-bsc/chan_alloc.c
@@ -113,8 +113,8 @@ bts_update_t3122_chan_load(struct gsm_bts *bts)
 
 		/* Ignore samples too large for fixed-point calculations (shouldn't happen). */
 		if (lc->used > UINT16_MAX || lc->total > UINT16_MAX) {
-			LOGP(DRLL, LOGL_NOTICE, "(bts=%d) numbers in channel load sample "
-			     "too large (used=%u / total=%u)\n", bts->nr, lc->used, lc->total);
+			LOG_BTS(bts, DRLL, LOGL_NOTICE, "numbers in channel load sample "
+				"too large (used=%u / total=%u)\n", lc->used, lc->total);
 			continue;
 		}
 
@@ -124,8 +124,8 @@ bts_update_t3122_chan_load(struct gsm_bts *bts)
 
 	/* Check for invalid samples (shouldn't happen). */
 	if (total == 0 || used > total) {
-		LOGP(DRLL, LOGL_NOTICE, "(bts=%d) bogus channel load sample (used=%"PRIu64" / total=%"PRIu32")\n",
-		     bts->nr, used, total);
+		LOG_BTS(bts, DRLL, LOGL_NOTICE, "bogus channel load sample (used=%"PRIu64" / total=%"PRIu32")\n",
+			used, total);
 		bts->T3122 = 0; /* disable override of network-wide default value */
 		bts->chan_load_samples_idx = 0; /* invalidate other samples collected so far */
 		return;
@@ -153,8 +153,8 @@ bts_update_t3122_chan_load(struct gsm_bts *bts)
 
 	/* Log channel load average. */
 	load = ((used / total) * 100);
-	LOGP(DRLL, LOGL_DEBUG, "(bts=%d) channel load average is %"PRIu64".%.2"PRIu64"%%\n",
-	     bts->nr, (load & 0xffffff00) >> 8, (load & 0xff) / 10);
+	LOG_BTS(bts, DRLL, LOGL_DEBUG, "channel load average is %"PRIu64".%.2"PRIu64"%%\n",
+		(load & 0xffffff00) >> 8, (load & 0xff) / 10);
 	bts->chan_load_avg = ((load & 0xffffff00) >> 8);
 	OSMO_ASSERT(bts->chan_load_avg <= 100);
 	osmo_stat_item_set(bts->bts_statg->items[BTS_STAT_CHAN_LOAD_AVERAGE], bts->chan_load_avg);
@@ -167,7 +167,7 @@ bts_update_t3122_chan_load(struct gsm_bts *bts)
 	else if (wait_ind > max_wait_ind)
 		wait_ind = max_wait_ind;
 
-	LOGP(DRLL, LOGL_DEBUG, "(bts=%d) T3122 wait indicator set to %"PRIu64" seconds\n", bts->nr, wait_ind);
+	LOG_BTS(bts, DRLL, LOGL_DEBUG, "T3122 wait indicator set to %"PRIu64" seconds\n", wait_ind);
 	bts->T3122 = (uint8_t)wait_ind;
 	osmo_stat_item_set(bts->bts_statg->items[BTS_STAT_T3122], wait_ind);
 }
diff --git a/src/osmo-bsc/e1_config.c b/src/osmo-bsc/e1_config.c
index e7398ed9c..4389f66c9 100644
--- a/src/osmo-bsc/e1_config.c
+++ b/src/osmo-bsc/e1_config.c
@@ -72,17 +72,15 @@ int e1_reconfig_trx(struct gsm_bts_trx *trx)
 	int i;
 
 	if (!e1_link->e1_ts) {
-		LOGP(DLINP, LOGL_ERROR, "TRX (%u/%u) RSL link without "
-		     "timeslot?\n", trx->bts->nr, trx->nr);
+		LOG_TRX(trx, DLINP, LOGL_ERROR, "RSL link without timeslot?\n");
 		return -EINVAL;
 	}
 
 	/* RSL Link */
 	line = e1inp_line_find(e1_link->e1_nr);
 	if (!line) {
-		LOGP(DLINP, LOGL_ERROR, "TRX (%u/%u) RSL link referring "
-		     "to non-existing E1 line %u\n", trx->bts->nr,
-		     trx->nr, e1_link->e1_nr);
+		LOG_TRX(trx, DLINP, LOGL_ERROR, "TRX RSL link referring to non-existing E1 line %u\n",
+			e1_link->e1_nr);
 		return -ENOMEM;
 	}
 	sign_ts = &line->ts[e1_link->e1_ts-1];
@@ -93,8 +91,7 @@ int e1_reconfig_trx(struct gsm_bts_trx *trx)
 		oml_link = e1inp_sign_link_create(sign_ts, E1INP_SIGN_OML, trx,
 						  trx->rsl_tei, SAPI_OML);
 		if (!oml_link) {
-			LOGP(DLINP, LOGL_ERROR, "TRX (%u/%u) OML link creation "
-				"failed\n", trx->bts->nr, trx->nr);
+			LOG_TRX(trx, DLINP, LOGL_ERROR, "TRX OML link creation failed\n");
 			return -ENOMEM;
 		}
 		if (trx->oml_link)
@@ -104,8 +101,7 @@ int e1_reconfig_trx(struct gsm_bts_trx *trx)
 	rsl_link = e1inp_sign_link_create(sign_ts, E1INP_SIGN_RSL,
 					  trx, trx->rsl_tei, SAPI_RSL);
 	if (!rsl_link) {
-		LOGP(DLINP, LOGL_ERROR, "TRX (%u/%u) RSL link creation "
-		     "failed\n", trx->bts->nr, trx->nr);
+		LOG_TRX(trx, DLINP, LOGL_ERROR, "TRX RSL link creation failed\n");
 		return -ENOMEM;
 	}
 	if (trx->rsl_link)
@@ -132,8 +128,8 @@ static int bts_isdn_sign_link(struct msgb *msg)
 		break;
 	case E1INP_SIGN_RSL:
 		if (link->trx->mo.nm_state.administrative == NM_STATE_LOCKED) {
-			LOGP(DLMI, LOGL_ERROR, "(bts=%d/trx=%d) discarding RSL message received "
-			     "in locked administrative state\n", link->trx->bts->nr, link->trx->nr);
+			LOG_TRX(link->trx, DLMI, LOGL_ERROR, "discarding RSL message received "
+			     "in locked administrative state\n");
 			msgb_free(msg);
 			break;
 		}
@@ -161,17 +157,17 @@ int e1_reconfig_bts(struct gsm_bts *bts)
 	struct timespec tp;
 	int rc;
 
-	DEBUGP(DLMI, "e1_reconfig_bts(%u)\n", bts->nr);
+	LOG_BTS(bts, DLMI, LOGL_DEBUG, "e1_reconfig_bts\n");
 
 	line = e1inp_line_find(e1_link->e1_nr);
 	if (!line) {
-		LOGP(DLINP, LOGL_ERROR, "BTS %u OML link referring to "
-		     "non-existing E1 line %u\n", bts->nr, e1_link->e1_nr);
+		LOG_BTS(bts, DLINP, LOGL_ERROR, "BTS OML link referring to "
+		     "non-existing E1 line %u\n", e1_link->e1_nr);
 		return -ENOMEM;
 	}
 
 	if (!bts->model->e1line_bind_ops) {
-		LOGP(DLINP, LOGL_ERROR, "no callback to bind E1 line operations\n");
+		LOG_BTS(bts, DLINP, LOGL_ERROR, "no callback to bind E1 line operations\n");
 		return -EINVAL;
 	}
 	if (!line->ops)
@@ -184,8 +180,7 @@ int e1_reconfig_bts(struct gsm_bts *bts)
 
 	/* OML link */
 	if (!e1_link->e1_ts) {
-		LOGP(DLINP, LOGL_ERROR, "BTS %u OML link without timeslot?\n",
-		     bts->nr);
+		LOG_BTS(bts, DLINP, LOGL_ERROR, "BTS OML link without timeslot?\n");
 		return -EINVAL;
 	}
 
@@ -194,8 +189,7 @@ int e1_reconfig_bts(struct gsm_bts *bts)
 	oml_link = e1inp_sign_link_create(sign_ts, E1INP_SIGN_OML,
 					  bts->c0, bts->oml_tei, SAPI_OML);
 	if (!oml_link) {
-		LOGP(DLINP, LOGL_ERROR, "BTS %u OML link creation failed\n",
-		     bts->nr);
+		LOG_BTS(bts, DLINP, LOGL_ERROR, "BTS OML link creation failed\n");
 		return -ENOMEM;
 	}
 	if (bts->oml_link)
diff --git a/src/osmo-bsc/lchan_select.c b/src/osmo-bsc/lchan_select.c
index 0a9752e44..6df3b4a6b 100644
--- a/src/osmo-bsc/lchan_select.c
+++ b/src/osmo-bsc/lchan_select.c
@@ -169,7 +169,7 @@ struct gsm_lchan *lchan_select_by_type(struct gsm_bts *bts, enum gsm_chan_t type
 	struct gsm_lchan *lchan = NULL;
 	enum gsm_phys_chan_config first, first_cbch, second, second_cbch;
 
-	LOGP(DRLL, LOGL_DEBUG, "(bts=%d) lchan_select_by_type(%s)\n", bts->nr, gsm_lchant_name(type));
+	LOG_BTS(bts, DRLL, LOGL_DEBUG, "lchan_select_by_type(%s)\n", gsm_lchant_name(type));
 
 	switch (type) {
 	case GSM_LCHAN_SDCCH:
@@ -227,15 +227,15 @@ struct gsm_lchan *lchan_select_by_type(struct gsm_bts *bts, enum gsm_chan_t type
 		}
 		break;
 	default:
-		LOGP(DRLL, LOGL_ERROR, "Unknown gsm_chan_t %u\n", type);
+		LOG_BTS(bts, DRLL, LOGL_ERROR, "Unknown gsm_chan_t %u\n", type);
 	}
 
 	if (lchan) {
 		lchan->type = type;
 		LOG_LCHAN(lchan, LOGL_INFO, "Selected\n");
 	} else
-		LOGP(DRLL, LOGL_ERROR, "(bts=%d) Failed to select %s channel\n",
-		     bts->nr, gsm_lchant_name(type));
+		LOG_BTS(bts, DRLL, LOGL_ERROR, "Failed to select %s channel\n",
+			gsm_lchant_name(type));
 
 	return lchan;
 }
diff --git a/src/osmo-bsc/paging.c b/src/osmo-bsc/paging.c
index f1fd2ad61..ca52ee79f 100644
--- a/src/osmo-bsc/paging.c
+++ b/src/osmo-bsc/paging.c
@@ -85,9 +85,9 @@ static void page_ms(struct gsm_paging_request *request)
 
 	log_set_context(LOG_CTX_BSC_SUBSCR, request->bsub);
 
-	LOGP(DPAG, LOGL_INFO, "(bts=%d) Going to send paging commands: imsi: %s tmsi: "
-	     "0x%08x for ch. type %d (attempt %d)\n", bts->nr, request->bsub->imsi,
-	     request->bsub->tmsi, request->chan_type, request->attempts);
+	LOG_BTS(bts, DPAG, LOGL_INFO, "Going to send paging commands: imsi: %s tmsi: "
+		"0x%08x for ch. type %d (attempt %d)\n", request->bsub->imsi,
+		request->bsub->tmsi, request->chan_type, request->attempts);
 
 	if (request->bsub->tmsi == GSM_RESERVED_TMSI)
 		mi_len = gsm48_generate_mid_from_imsi(mi, request->bsub->imsi);
@@ -115,8 +115,7 @@ static void paging_give_credit(void *data)
 {
 	struct gsm_bts_paging_state *paging_bts = data;
 
-	LOGP(DPAG, LOGL_NOTICE, "(bts=%d) No PCH LOAD IND, adding 20 slots)\n",
-	     paging_bts->bts->nr);
+	LOG_BTS(paging_bts->bts, DPAG, LOGL_NOTICE, "No PCH LOAD IND, adding 20 slots)\n");
 	paging_bts->available_slots = 20;
 	paging_handle_pending_requests(paging_bts);
 }
@@ -315,8 +314,7 @@ static unsigned int calculate_timer_3113(struct gsm_bts *bts)
 
 	/* ceiling in seconds + extra time */
 	to = (to_us + 999999) / 1000000 + d->val;
-	LOGP(DPAG, LOGL_DEBUG, "(bts=%d) Paging request: T3113 expires in %u seconds\n",
-	     bts->nr, to);
+	LOG_BTS(bts, DPAG, LOGL_DEBUG, "Paging request: T3113 expires in %u seconds\n", to);
 	return to;
 }
 
@@ -336,14 +334,13 @@ static int _paging_request(struct gsm_bts *bts, struct bsc_subscr *bsub, int typ
 	rate_ctr_inc(&bts->bts_ctrs->ctr[BTS_CTR_PAGING_ATTEMPTED]);
 
 	if (paging_pending_request(bts_entry, bsub)) {
-		LOGP(DPAG, LOGL_INFO, "(bts=%d) Paging request already pending for %s\n",
-		     bts->nr, bsc_subscr_name(bsub));
+		LOG_BTS(bts, DPAG, LOGL_INFO, "Paging request already pending for %s\n",
+			bsc_subscr_name(bsub));
 		rate_ctr_inc(&bts->bts_ctrs->ctr[BTS_CTR_PAGING_ALREADY]);
 		return -EEXIST;
 	}
 
-	LOGP(DPAG, LOGL_DEBUG, "(bts=%d) Start paging of subscriber %s\n", bts->nr,
-	     bsc_subscr_name(bsub));
+	LOG_BTS(bts, DPAG, LOGL_DEBUG, "Start paging of subscriber %s\n", bsc_subscr_name(bsub));
 	req = talloc_zero(tall_paging_ctx, struct gsm_paging_request);
 	OSMO_ASSERT(req);
 	req->bsub = bsc_subscr_get(bsub);
@@ -407,8 +404,7 @@ static int _paging_request_stop(struct gsm_bts *bts, struct bsc_subscr *bsub,
 		if (req->bsub == bsub) {
 			/* now give up the data structure */
 			paging_remove_request(&bts->paging, req);
-			LOGP(DPAG, LOGL_DEBUG, "(bts=%d) Stop paging %s\n", bts->nr,
-			     bsc_subscr_name(bsub));
+			LOG_BTS(bts, DPAG, LOGL_DEBUG, "Stop paging %s\n", bsc_subscr_name(bsub));
 			return 0;
 		}
 	}
@@ -498,8 +494,7 @@ void paging_flush_bts(struct gsm_bts *bts, struct bsc_msc_data *msc)
 		if (msc && req->msc != msc)
 			continue;
 		/* now give up the data structure */
-		LOGP(DPAG, LOGL_DEBUG, "(bts=%d) Stop paging %s (flush)\n", bts->nr,
-		     bsc_subscr_name(req->bsub));
+		LOG_BTS(bts, DPAG, LOGL_DEBUG, "Stop paging %s (flush)\n", bsc_subscr_name(req->bsub));
 		paging_remove_request(&bts->paging, req);
 	}
 }