scheduler: Harmonize log line format; Always print TS name + decoded FN

Change-Id: I5703b46c8a59fe00a3cdc063bcf72872980ec5e5

3 files changed, 93 insertions, 144 deletions

diff --git a/include/osmo-bts/scheduler_backend.h b/include/osmo-bts/scheduler_backend.h
index af1cfbf4..5e077eff 100644
--- a/include/osmo-bts/scheduler_backend.h
+++ b/include/osmo-bts/scheduler_backend.h
@@ -1,5 +1,11 @@
 #pragma once
 
+#define LOGL1S(subsys, level, l1t, tn, chan, fn, fmt, args ...)	\
+		LOGP(subsys, level, "%s %s %s: " fmt,		\
+			gsm_fn_as_gsmtime_str(fn),		\
+			gsm_ts_name(&(l1t)->trx->ts[tn]),	\
+			chan >=0 ? trx_chan_desc[chan].name : "", ## args)
+
 typedef int trx_sched_rts_func(struct l1sched_trx *l1t, uint8_t tn,
 			       uint32_t fn, enum trx_chan_type chan);
 
diff --git a/src/common/scheduler.c b/src/common/scheduler.c
index f6cb07e5..efd76660 100644
--- a/src/common/scheduler.c
+++ b/src/common/scheduler.c
@@ -282,8 +282,7 @@ struct msgb *_sched_dequeue_prim(struct l1sched_trx *l1t, int8_t tn, uint32_t fn
 		l1sap = msgb_l1sap_prim(msg);
 		if (l1sap->oph.operation != PRIM_OP_REQUEST) {
 wrong_type:
-			LOGP(DL1P, LOGL_ERROR, "Prim for ts=%u at fn=%u has "
-				"wrong type.\n", tn, fn);
+			LOGL1S(DL1P, LOGL_ERROR, l1t, tn, chan, fn, "Prim has wrong type.\n");
 free_msg:
 			/* unlink and free message */
 			llist_del(&msg->list);
@@ -305,14 +304,12 @@ free_msg:
 			goto wrong_type;
 		}
 		if (prim_fn > 100) {
-			LOGP(DL1P, LOGL_NOTICE, "Prim %u for trx=%u ts=%u at "
-			     "fn=%u is out of range (100), or channel %s with "
+			LOGL1S(DL1P, LOGL_NOTICE, l1t, tn, chan, fn,
+			     "Prim %u is out of range (100), or channel %s with "
 			     "type %s is already disabled. If this happens in "
-			     "conjunction with PCU, increase 'rts-advance' by 5."
-			     " (current fn=%u)\n", prim_fn, l1t->trx->nr, tn,
-			     l1sap->u.data.fn,
-			     get_lchan_by_chan_nr(l1t->trx, chan_nr)->name,
-			     get_value_string(trx_chan_type_names, chan), fn);
+			     "conjunction with PCU, increase 'rts-advance' by 5.",
+			     prim_fn, get_lchan_by_chan_nr(l1t->trx, chan_nr)->name,
+			     get_value_string(trx_chan_type_names, chan));
 			/* unlink and free message */
 			llist_del(&msg->list);
 			msgb_free(msg);
@@ -329,11 +326,9 @@ free_msg:
 found_msg:
 	if ((chan_nr ^ (trx_chan_desc[chan].chan_nr | tn))
 	 || ((link_id & 0xc0) ^ trx_chan_desc[chan].link_id)) {
-		LOGP(DL1P, LOGL_ERROR, "Prim for ts=%u at fn=%u has wrong "
-			"chan_nr=%02x link_id=%02x, expecting chan_nr=%02x "
-			"link_id=%02x.\n", tn, fn, chan_nr, link_id,
-			trx_chan_desc[chan].chan_nr | tn,
-			trx_chan_desc[chan].link_id);
+		LOGL1S(DL1P, LOGL_ERROR, l1t, tn, chan, fn, "Prim has wrong chan_nr=%02x link_id=%02x, "
+			"expecting chan_nr=%02x link_id=%02x.\n", chan_nr, link_id,
+			trx_chan_desc[chan].chan_nr | tn, trx_chan_desc[chan].link_id);
 		goto free_msg;
 	}
 
@@ -418,9 +413,9 @@ int trx_sched_ph_data_req(struct l1sched_trx *l1t, struct osmo_phsap_prim *l1sap
 	uint8_t tn = l1sap->u.data.chan_nr & 7;
 	struct l1sched_ts *l1ts = l1sched_trx_get_ts(l1t, tn);
 
-	LOGP(DL1P, LOGL_INFO, "PH-DATA.req: chan_nr=0x%02x link_id=0x%02x "
-		"fn=%u ts=%u trx=%u\n", l1sap->u.data.chan_nr,
-		l1sap->u.data.link_id, l1sap->u.data.fn, tn, l1t->trx->nr);
+	LOGL1S(DL1P, LOGL_INFO, l1t, tn, -1, l1sap->u.data.fn,
+		"PH-DATA.req: chan_nr=0x%02x link_id=0x%02x\n",
+		l1sap->u.data.chan_nr, l1sap->u.data.link_id);
 
 	if (!l1sap->oph.msg)
 		abort();
@@ -441,9 +436,8 @@ int trx_sched_tch_req(struct l1sched_trx *l1t, struct osmo_phsap_prim *l1sap)
 	uint8_t tn = l1sap->u.tch.chan_nr & 7;
 	struct l1sched_ts *l1ts = l1sched_trx_get_ts(l1t, tn);
 
-	LOGP(DL1P, LOGL_INFO, "TCH.req: chan_nr=0x%02x "
-		"fn=%u ts=%u trx=%u\n", l1sap->u.tch.chan_nr,
-		l1sap->u.tch.fn, tn, l1t->trx->nr);
+	LOGL1S(DL1P, LOGL_INFO, l1t, tn, -1, l1sap->u.tch.fn, "TCH.req: chan_nr=0x%02x\n",
+		l1sap->u.tch.chan_nr);
 
 	if (!l1sap->oph.msg)
 		abort();
@@ -477,14 +471,13 @@ static int rts_data_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	link_id = trx_chan_desc[chan].link_id;
 
 	if (!chan_nr) {
-		LOGP(DL1P, LOGL_FATAL, "RTS func for %s with non-existing "
-			"chan_nr %d\n", trx_chan_desc[chan].name, chan_nr);
+		LOGL1S(DL1P, LOGL_FATAL, l1t, tn, chan, fn,
+			"RTS func with non-existing chan_nr %d\n", chan_nr);
 		return -ENODEV;
 	}
 
-	LOGP(DL1P, LOGL_INFO, "PH-RTS.ind: chan=%s chan_nr=0x%02x "
-		"link_id=0x%02x fn=%u ts=%u trx=%u\n", trx_chan_desc[chan].name,
-		chan_nr, link_id, fn, tn, l1t->trx->nr);
+	LOGL1S(DL1P, LOGL_INFO, l1t, tn, chan, fn,
+		"PH-RTS.ind: chan_nr=0x%02x link_id=0x%02x\n", chan_nr, link_id);
 
 	/* generate prim */
 	msg = l1sap_msgb_alloc(200);
@@ -514,14 +507,12 @@ static int rts_tch_common(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	link_id = trx_chan_desc[chan].link_id;
 
 	if (!chan_nr) {
-		LOGP(DL1P, LOGL_FATAL, "RTS func for %s with non-existing "
-			"chan_nr %d\n", trx_chan_desc[chan].name, chan_nr);
+		LOGL1S(DL1P, LOGL_FATAL, l1t, tn, chan, fn,
+			"RTS func with non-existing chan_nr %d\n", chan_nr);
 		return -ENODEV;
 	}
 
-	LOGP(DL1P, LOGL_INFO, "TCH RTS.ind: chan=%s chan_nr=0x%02x "
-		"fn=%u ts=%u trx=%u\n", trx_chan_desc[chan].name,
-		chan_nr, fn, tn, l1t->trx->nr);
+	LOGL1S(DL1P, LOGL_INFO, l1t, tn, chan, fn, "TCH RTS.ind: chan_nr=0x%02x\n", chan_nr);
 
 	/* only send, if FACCH is selected */
 	if (facch) {
diff --git a/src/osmo-bts-trx/scheduler_trx.c b/src/osmo-bts-trx/scheduler_trx.c
index c849dd52..81984c21 100644
--- a/src/osmo-bts-trx/scheduler_trx.c
+++ b/src/osmo-bts-trx/scheduler_trx.c
@@ -75,8 +75,7 @@ static inline uint16_t compute_ber10k(int n_bits_total, int n_errors)
 ubit_t *tx_idle_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	enum trx_chan_type chan, uint8_t bid, uint16_t *nbits)
 {
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting IDLE\n");
 
 	if (nbits)
 		*nbits = GSM_BURST_LEN;
@@ -88,8 +87,7 @@ ubit_t *tx_idle_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 ubit_t *tx_fcch_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	enum trx_chan_type chan, uint8_t bid, uint16_t *nbits)
 {
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting FCCH\n");
 
 	if (nbits)
 		*nbits = GSM_BURST_LEN;
@@ -108,8 +106,7 @@ ubit_t *tx_sch_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	struct	gsm_time t;
 	uint8_t t3p, bsic;
 
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting SCH\n");
 
 	/* BURST BYPASS */
 
@@ -173,9 +170,7 @@ ubit_t *tx_data_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	if (msg)
 		goto got_msg;
 
-	LOGP(DL1C, LOGL_INFO, "%s has not been served !! No prim for "
-		"trx=%u ts=%u at fn=%u to transmit.\n",
-		trx_chan_desc[chan].name, l1t->trx->nr, tn, fn);
+	LOGL1S(DL1C, LOGL_INFO, l1t, tn, chan, fn, "No prim for transmit.\n");
 
 no_msg:
 	/* free burst memory */
@@ -188,7 +183,7 @@ no_msg:
 got_msg:
 	/* check validity of message */
 	if (msgb_l2len(msg) != GSM_MACBLOCK_LEN) {
-		LOGP(DL1C, LOGL_FATAL, "Prim not 23 bytes, please FIX! "
+		LOGL1S(DL1C, LOGL_FATAL, l1t, tn, chan, fn, "Prim not 23 bytes, please FIX! "
 			"(len=%d)\n", msgb_l2len(msg));
 		/* free message */
 		msgb_free(msg);
@@ -239,8 +234,7 @@ send_burst:
 	if (nbits)
 		*nbits = GSM_BURST_LEN;
 
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u burst=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting burst=%u.\n", bid);
 
 	return bits;
 }
@@ -269,9 +263,7 @@ ubit_t *tx_pdtch_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	if (msg)
 		goto got_msg;
 
-	LOGP(DL1C, LOGL_INFO, "%s has not been served !! No prim for "
-		"trx=%u ts=%u at fn=%u to transmit.\n",
-		trx_chan_desc[chan].name, l1t->trx->nr, tn, fn);
+	LOGL1S(DL1C, LOGL_INFO, l1t, tn, chan, fn, "No prim for transmit.\n");
 
 no_msg:
 	/* free burst memory */
@@ -299,7 +291,7 @@ got_msg:
 
 	/* check validity of message */
 	if (rc < 0) {
-		LOGP(DL1C, LOGL_FATAL, "Prim invalid length, please FIX! "
+		LOGL1S(DL1C, LOGL_FATAL, l1t, tn, chan, fn, "Prim invalid length, please FIX! "
 			"(len=%ld)\n", msg->tail - msg->l2h);
 		/* free message */
 		msgb_free(msg);
@@ -337,8 +329,7 @@ send_burst:
 			*nbits = GSM_BURST_LEN;
 	}
 
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u burst=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting burst=%u.\n", bid);
 
 	return bits;
 }
@@ -367,8 +358,8 @@ static void tx_tch_common(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 		uint8_t tch_data[GSM_FR_BYTES];
 		int len;
 
-		LOGP(DL1C, LOGL_NOTICE, "Missing TCH bursts detected, sending "
-			"BFI for %s\n", trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn,
+			"Missing TCH bursts detected, sending BFI\n");
 
 		/* indicate bad frame */
 		switch (tch_mode) {
@@ -399,8 +390,7 @@ static void tx_tch_common(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 			break;
 		default:
 inval_mode1:
-			LOGP(DL1C, LOGL_ERROR, "TCH mode invalid, please "
-				"fix!\n");
+			LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "TCH mode invalid, please fix!\n");
 			len = 0;
 		}
 		if (len)
@@ -417,8 +407,8 @@ inval_mode1:
 			if (msg2) {
 				l1sap = msgb_l1sap_prim(msg2);
 				if (l1sap->oph.primitive == PRIM_TCH) {
-					LOGP(DL1C, LOGL_FATAL, "TCH twice, "
-						"please FIX! ");
+					LOGL1S(DL1C, LOGL_FATAL, l1t, tn, chan, fn,
+						"TCH twice, please FIX!\n");
 					msgb_free(msg2);
 				} else
 					msg_facch = msg2;
@@ -428,8 +418,8 @@ inval_mode1:
 			if (msg2) {
 				l1sap = msgb_l1sap_prim(msg2);
 				if (l1sap->oph.primitive != PRIM_TCH) {
-					LOGP(DL1C, LOGL_FATAL, "FACCH twice, "
-						"please FIX! ");
+					LOGL1S(DL1C, LOGL_FATAL, l1t, tn, chan, fn,
+						"FACCH twice, please FIX!\n");
 					msgb_free(msg2);
 				} else
 					msg_tch = msg2;
@@ -445,7 +435,7 @@ inval_mode1:
 
 	/* check validity of message */
 	if (msg_facch && msgb_l2len(msg_facch) != GSM_MACBLOCK_LEN) {
-		LOGP(DL1C, LOGL_FATAL, "Prim not 23 bytes, please FIX! "
+		LOGL1S(DL1C, LOGL_FATAL, l1t, tn, chan, fn, "Prim not 23 bytes, please FIX! "
 			"(len=%d)\n", msgb_l2len(msg_facch));
 		/* free message */
 		msgb_free(msg_facch);
@@ -462,10 +452,8 @@ inval_mode1:
 		int8_t sti, cmi;
 
 		if (rsl_cmode != RSL_CMOD_SPD_SPEECH) {
-			LOGP(DL1C, LOGL_NOTICE, "%s Dropping speech frame, "
-				"because we are not in speech mode trx=%u "
-				"ts=%u at fn=%u.\n", trx_chan_desc[chan].name,
-				l1t->trx->nr, tn, fn);
+			LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Dropping speech frame, "
+				"because we are not in speech mode\n");
 			goto free_bad_msg;
 		}
 
@@ -502,43 +490,33 @@ inval_mode1:
 				trx_loop_amr_set(chan_state, 1);
 			}
 			if (ft < 0) {
-				LOGP(DL1C, LOGL_ERROR, "%s Codec (FT = %d) "
-					" of RTP frame not in list. "
-					"trx=%u ts=%u\n",
-					trx_chan_desc[chan].name, ft_codec,
-					l1t->trx->nr, tn);
+				LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn,
+					"Codec (FT = %d) of RTP frame not in list\n", ft_codec);
 				goto free_bad_msg;
 			}
 			if (fn_is_codec_mode_request(fn) && chan_state->dl_ft != ft) {
-				LOGP(DL1C, LOGL_NOTICE, "%s Codec (FT = %d) "
-					" of RTP cannot be changed now, but in "
-					"next frame. trx=%u ts=%u\n",
-					trx_chan_desc[chan].name, ft_codec,
-					l1t->trx->nr, tn);
+				LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Codec (FT = %d) "
+					" of RTP cannot be changed now, but in next frame\n", ft_codec);
 				goto free_bad_msg;
 			}
 			chan_state->dl_ft = ft;
 			if (bfi == AMR_BAD) {
-				LOGP(DL1C, LOGL_NOTICE, "%s Transmitting 'bad "
-					"AMR frame' trx=%u ts=%u at fn=%u.\n",
-					trx_chan_desc[chan].name,
-					l1t->trx->nr, tn, fn);
+				LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn,
+					"Transmitting 'bad AMR frame'\n");
 				goto free_bad_msg;
 			}
 			break;
 		default:
 inval_mode2:
-			LOGP(DL1C, LOGL_ERROR, "TCH mode invalid, please "
-				"fix!\n");
+			LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "TCH mode invalid, please fix!\n");
 			goto free_bad_msg;
 		}
 		if (len < 0) {
-			LOGP(DL1C, LOGL_ERROR, "Cannot send invalid AMR "
-				"payload\n");
+			LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "Cannot send invalid AMR payload\n");
 			goto free_bad_msg;
 		}
 		if (msgb_l2len(msg_tch) != len) {
-			LOGP(DL1C, LOGL_ERROR, "Cannot send payload with "
+			LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "Cannot send payload with "
 				"invalid length! (expecting %d, received %d)\n",
 				len, msgb_l2len(msg_tch));
 free_bad_msg:
@@ -590,9 +568,7 @@ ubit_t *tx_tchf_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* no message at all */
 	if (!msg_tch && !msg_facch) {
-		LOGP(DL1C, LOGL_INFO, "%s has not been served !! No prim for "
-			"trx=%u ts=%u at fn=%u to transmit.\n",
-			trx_chan_desc[chan].name, l1t->trx->nr, tn, fn);
+		LOGL1S(DL1C, LOGL_INFO, l1t, tn, chan, fn, "No TCH or FACCH prim for transmit.\n");
 		goto send_burst;
 	}
 
@@ -630,8 +606,7 @@ send_burst:
 	if (nbits)
 		*nbits = GSM_BURST_LEN;
 
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u burst=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting burst=%u.\n", bid);
 
 	return bits;
 }
@@ -660,9 +635,8 @@ ubit_t *tx_tchh_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* check for FACCH alignment */
 	if (msg_facch && ((((fn + 4) % 26) >> 2) & 1)) {
-		LOGP(DL1C, LOGL_ERROR, "%s Cannot transmit FACCH starting on "
-			"even frames, please fix RTS!\n",
-			trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "Cannot transmit FACCH starting on "
+			"even frames, please fix RTS!\n");
 		msgb_free(msg_facch);
 		msg_facch = NULL;
 	}
@@ -687,9 +661,7 @@ ubit_t *tx_tchh_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* no message at all */
 	if (!msg_tch && !msg_facch && !chan_state->dl_ongoing_facch) {
-		LOGP(DL1C, LOGL_INFO, "%s has not been served !! No prim for "
-			"trx=%u ts=%u at fn=%u to transmit.\n",
-			trx_chan_desc[chan].name, l1t->trx->nr, tn, fn);
+		LOGL1S(DL1C, LOGL_INFO, l1t, tn, chan, fn, "No TCH or FACCH prim for transmit.\n");
 		goto send_burst;
 	}
 
@@ -729,8 +701,7 @@ send_burst:
 	if (nbits)
 		*nbits = GSM_BURST_LEN;
 
-	LOGP(DL1C, LOGL_DEBUG, "Transmitting %s fn=%u ts=%u trx=%u burst=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Transmitting burst=%u.\n", bid);
 
 	return bits;
 }
@@ -751,14 +722,12 @@ int rx_rach_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	chan_nr = trx_chan_desc[chan].chan_nr | tn;
 
-	LOGP(DL1C, LOGL_DEBUG, "Received Access Burst on %s fn=%u toa=%.2f\n",
-		trx_chan_desc[chan].name, fn, toa);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received RACH toa=%.2f\n", toa);
 
 	/* decode */
 	rc = gsm0503_rach_decode(&ra, bits + 8 + 41, l1t->trx->bts->bsic);
 	if (rc) {
-		LOGP(DL1C, LOGL_DEBUG, "Received bad AB frame at fn=%u "
-			"(%u/51)\n", fn, fn % 51);
+		LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received bad AB frame\n");
 		return 0;
 	}
 
@@ -809,8 +778,7 @@ int rx_data_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	if (chan_state->ho_rach_detect == 1)
 		return rx_rach_fn(l1t, tn, fn, chan, bid, bits, GSM_BURST_LEN, rssi, toa);
 
-	LOGP(DL1C, LOGL_DEBUG, "Data received %s fn=%u ts=%u trx=%u bid=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received Data, bid=%u\n", bid);
 
 	/* allocate burst memory, if not already */
 	if (!*bursts_p) {
@@ -854,10 +822,8 @@ int rx_data_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* check for complete set of bursts */
 	if ((*mask & 0xf) != 0xf) {
-		LOGP(DL1C, LOGL_NOTICE, "Received incomplete data frame at "
-			"fn=%u (%u/%u) for %s\n", *first_fn,
-			(*first_fn) % l1ts->mf_period, l1ts->mf_period,
-			trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received incomplete data (%u/%u)\n",
+			*first_fn, (*first_fn) % l1ts->mf_period);
 
 		/* we require first burst to have correct FN */
 		if (!(*mask & 0x1)) {
@@ -870,10 +836,8 @@ int rx_data_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	/* decode */
 	rc = gsm0503_xcch_decode(l2, *bursts_p, &n_errors, &n_bits_total);
 	if (rc) {
-		LOGP(DL1C, LOGL_DEBUG, "Received bad data frame at fn=%u "
-			"(%u/%u) for %s\n", *first_fn,
-			(*first_fn) % l1ts->mf_period, l1ts->mf_period,
-			trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received bad data (%u/%u)\n",
+			*first_fn, (*first_fn) % l1ts->mf_period);
 		l2_len = 0;
 	} else
 		l2_len = GSM_MACBLOCK_LEN;
@@ -906,8 +870,7 @@ int rx_pdtch_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	uint16_t ber10k;
 	int rc;
 
-	LOGP(DL1C, LOGL_DEBUG, "PDTCH received %s fn=%u ts=%u trx=%u bid=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received PDTCH bid=%u\n", bid);
 
 	/* allocate burst memory, if not already */
 	if (!*bursts_p) {
@@ -953,10 +916,8 @@ int rx_pdtch_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* check for complete set of bursts */
 	if ((*mask & 0xf) != 0xf) {
-		LOGP(DL1C, LOGL_DEBUG, "Received incomplete PDTCH block "
-			"ending at fn=%u (%u/%u) for %s\n", fn,
-			fn % l1ts->mf_period, l1ts->mf_period,
-			trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received incomplete frame (%u/%u)\n",
+			fn % l1ts->mf_period, l1ts->mf_period);
 	}
 	*mask = 0x0;
 
@@ -980,9 +941,8 @@ int rx_pdtch_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 		n_errors, n_bits_total, *rssi_sum / *rssi_num, *toa_sum / *toa_num);
 
 	if (rc <= 0) {
-		LOGP(DL1C, LOGL_DEBUG, "Received bad PDTCH block ending at "
-			"fn=%u (%u/%u) for %s\n", fn, fn % l1ts->mf_period,
-			l1ts->mf_period, trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received bad PDTCH (%u/%u)\n",
+			fn % l1ts->mf_period, l1ts->mf_period);
 		return 0;
 	}
 	ber10k = compute_ber10k(n_bits_total, n_errors);
@@ -1012,8 +972,7 @@ int rx_tchf_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	if (chan_state->ho_rach_detect == 1)
 		return rx_rach_fn(l1t, tn, fn, chan, bid, bits, GSM_BURST_LEN, rssi, toa);
 
-	LOGP(DL1C, LOGL_DEBUG, "TCH/F received %s fn=%u ts=%u trx=%u bid=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received TCH/F, bid=%u\n", bid);
 
 	/* allocate burst memory, if not already */
 	if (!*bursts_p) {
@@ -1042,10 +1001,8 @@ int rx_tchf_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* check for complete set of bursts */
 	if ((*mask & 0xf) != 0xf) {
-		LOGP(DL1C, LOGL_NOTICE, "Received incomplete TCH frame ending "
-			"at fn=%u (%u/%u) for %s\n", fn,
-			fn % l1ts->mf_period, l1ts->mf_period,
-			trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received incomplete frame (%u/%u)\n",
+			fn % l1ts->mf_period, l1ts->mf_period);
 	}
 	*mask = 0x0;
 
@@ -1083,7 +1040,7 @@ int rx_tchf_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 		}
 		break;
 	default:
-		LOGP(DL1C, LOGL_ERROR, "TCH mode %u invalid, please fix!\n",
+		LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "TCH mode %u invalid, please fix!\n",
 			tch_mode);
 		return -EINVAL;
 	}
@@ -1095,14 +1052,13 @@ int rx_tchf_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* Check if the frame is bad */
 	if (rc < 0) {
-		LOGP(DL1C, LOGL_NOTICE, "Received bad TCH frame ending at "
-			"fn=%u for %s\n", fn, trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received bad data (%u/%u)\n",
+			fn % l1ts->mf_period, l1ts->mf_period);
 		goto bfi;
 	}
 	if (rc < 4) {
-		LOGP(DL1C, LOGL_NOTICE, "Received bad TCH frame ending at "
-			"fn=%u for %s with codec mode %d (out of range)\n",
-			fn, trx_chan_desc[chan].name, rc);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received bad data (%u/%u) "
+			"with invalid codec mode %d\n", fn % l1ts->mf_period, l1ts->mf_period, rc);
 		goto bfi;
 	}
 
@@ -1138,8 +1094,8 @@ bfi:
 				memset(tch_data + 2, 0, rc - 2);
 				break;
 			default:
-				LOGP(DL1C, LOGL_ERROR, "TCH mode invalid, "
-					"please fix!\n");
+				LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn,
+					"TCH mode %u invalid, please fix!\n", tch_mode);
 				return -EINVAL;
 			}
 		}
@@ -1179,8 +1135,7 @@ int rx_tchh_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 	if (chan_state->ho_rach_detect == 1)
 		return rx_rach_fn(l1t, tn, fn, chan, bid, bits, GSM_BURST_LEN, rssi, toa);
 
-	LOGP(DL1C, LOGL_DEBUG, "TCH/H received %s fn=%u ts=%u trx=%u bid=%u\n",
-		trx_chan_desc[chan].name, fn, tn, l1t->trx->nr, bid);
+	LOGL1S(DL1C, LOGL_DEBUG, l1t, tn, chan, fn, "Received TCH/H, bid=%u\n", bid);
 
 	/* allocate burst memory, if not already */
 	if (!*bursts_p) {
@@ -1209,10 +1164,8 @@ int rx_tchh_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* check for complete set of bursts */
 	if ((*mask & 0x3) != 0x3) {
-		LOGP(DL1C, LOGL_NOTICE, "Received incomplete TCH frame ending "
-			"at fn=%u (%u/%u) for %s\n", fn,
-			fn % l1ts->mf_period, l1ts->mf_period,
-			trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received incomplete frame (%u/%u)\n",
+			fn % l1ts->mf_period, l1ts->mf_period);
 	}
 	*mask = 0x0;
 
@@ -1260,7 +1213,7 @@ int rx_tchh_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 		}
 		break;
 	default:
-		LOGP(DL1C, LOGL_ERROR, "TCH mode %u invalid, please fix!\n",
+		LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn, "TCH mode %u invalid, please fix!\n",
 			tch_mode);
 		return -EINVAL;
 	}
@@ -1273,14 +1226,13 @@ int rx_tchh_fn(struct l1sched_trx *l1t, uint8_t tn, uint32_t fn,
 
 	/* Check if the frame is bad */
 	if (rc < 0) {
-		LOGP(DL1C, LOGL_NOTICE, "Received bad TCH frame ending at "
-			"fn=%u for %s\n", fn, trx_chan_desc[chan].name);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received bad data (%u/%u)\n",
+			fn % l1ts->mf_period, l1ts->mf_period);
 		goto bfi;
 	}
 	if (rc < 4) {
-		LOGP(DL1C, LOGL_NOTICE, "Received bad TCH frame ending at "
-			"fn=%u for %s with codec mode %d (out of range)\n",
-			fn, trx_chan_desc[chan].name, rc);
+		LOGL1S(DL1C, LOGL_NOTICE, l1t, tn, chan, fn, "Received bad data (%u/%u) "
+			"with invalid codec mode %d\n", fn % l1ts->mf_period, l1ts->mf_period, rc);
 		goto bfi;
 	}
 
@@ -1313,8 +1265,8 @@ bfi:
 				memset(tch_data + 2, 0, rc - 2);
 				break;
 			default:
-				LOGP(DL1C, LOGL_ERROR, "TCH mode invalid, "
-					"please fix!\n");
+				LOGL1S(DL1C, LOGL_ERROR, l1t, tn, chan, fn,
+					"TCH mode %u invalid, please fix!\n", tch_mode);
 				return -EINVAL;
 			}
 		}