hodec2 log: less verbose, more concise logging

Drop numerous log statements that merely bloat the ho decision log.

Logging HO candidates: log more compact in a single line, do not use LOGPC and
multiline output. The result is more useful information in a quarter of the log
lines.

LOGPHOLCHAN(), LOGPHOLCHANTOBTS():
- log lchan->type instead of lchan->ts->pchan
- always log the speech mode

===== Before =====

DHODEC handover_decision_2.c:1131 (lchan 0.010 TCH/F) (subscr IMSI:000001) MEASUREMENT REPORT (1 neighbors)
DHODEC handover_decision_2.c:1136 (lchan 0.010 TCH/F) (subscr IMSI:000001)   0: arfcn=871 bsic=63 neigh_idx=0 rxlev=30 flags=0
DHODEC handover_decision_2.c:261 (lchan 0.010 TCH/F) (subscr IMSI:000001) neigh 871 rxlev=30 last_seen_nr=3
DHODEC handover_decision_2.c:1158 (lchan 0.010 TCH/F) (subscr IMSI:000001) HODEC2: evaluating measurement report
DHODEC handover_decision_2.c:1175 (lchan 0.010 TCH/F) (subscr IMSI:000001) Measurement report: average RX level = -110
DHODEC handover_decision_2.c:1190 (lchan 0.010 TCH/F) (subscr IMSI:000001) Virtually improving RX level from -110 to -105, due to AFS bias
DHODEC handover_decision_2.c:1220 (lchan 0.010 TCH/F) (subscr IMSI:000001) Attempting handover/assignment due to low rxlev
DHODEC handover_decision_2.c:899 (lchan 0.010 TCH/F) (subscr IMSI:000001) Collecting candidates for Assignment and Handover
DHODEC handover_decision_2.c:407 (lchan 0.010 TCH/F)->(BTS 0) (subscr IMSI:000001) tch_mode='SPEECH_AMR' type='TCH_F'
DHODEC handover_decision_2.c:313 (lchan 0.010 TCH/F) (subscr IMSI:000001) FR3 supported
DHODEC handover_decision_2.c:313 (lchan 0.010 TCH/F) (subscr IMSI:000001) HR3 supported
DHODEC handover_decision_2.c:489 (lchan 0.010 TCH/F)->(BTS 0) (subscr IMSI:000001) removing TCH/F, already on TCH/F in this cell
DHODEC handover_decision_2.c:573 (lchan 0.010 TCH/F)->(BTS 0) (subscr IMSI:000001) TCH/H would not be congested after HO
DHODEC handover_decision_2.c:605 (lchan 0.010 TCH/F)->(BTS 0) (subscr IMSI:000001) TCH/H would not be less congested in target than source cell after HO
DHODEC handover_decision_2.c:609 (lchan 0.010 TCH/F)->(BTS 0) (subscr IMSI:000001) requirements=0x30
DHODEC handover_decision_2.c:704  - current BTS 0, RX level -110
DHODEC handover_decision_2.c:707    o free TCH/F slots 3, minimum required 0
DHODEC handover_decision_2.c:709    o free TCH/H slots 4, minimum required 0
DHODEC handover_decision_2.c:714    o no requirement fulfilled for TCHF (no assignment possible)
DHODEC handover_decision_2.c:737    o requirement A B fulfilled for TCHH (not congested after assignment)
DHODEC handover_decision_2.c:407 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) tch_mode='SPEECH_AMR' type='TCH_F'
DHODEC handover_decision_2.c:313 (lchan 0.010 TCH/F) (subscr IMSI:000001) FR3 supported
DHODEC handover_decision_2.c:313 (lchan 0.010 TCH/F) (subscr IMSI:000001) HR3 supported
DHODEC handover_decision_2.c:563 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) TCH/F would not be congested after HO
DHODEC handover_decision_2.c:573 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) TCH/H would not be congested after HO
DHODEC handover_decision_2.c:595 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) TCH/F would not be less congested in target than source cell after HO
DHODEC handover_decision_2.c:605 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) TCH/H would not be less congested in target than source cell after HO
DHODEC handover_decision_2.c:609 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) requirements=0x33
DHODEC handover_decision_2.c:701  - neighbor BTS 1, RX level -110 -> -80
DHODEC handover_decision_2.c:707    o free TCH/F slots 4, minimum required 0
DHODEC handover_decision_2.c:709    o free TCH/H slots 4, minimum required 0
DHODEC handover_decision_2.c:712    o requirement A B fulfilled for TCHF (not congested after handover)
DHODEC handover_decision_2.c:737    o requirement A B fulfilled for TCHH (not congested after handover)
DHODEC handover_decision_2.c:914 (lchan 0.010 TCH/F) (subscr IMSI:000001) adding 2 candidates from 1 neighbors, total 2
DHODEC handover_decision_2.c:1020 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) Best candidate, RX level -80
DHODEC handover_decision_2.c:625 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) Triggering Handover
DHODEC handover_decision_2.c:688 (lchan 0.010 TCH/F)->(BTS 1) (subscr IMSI:000001) Triggering handover to TCH/F, due to low rxlevel
DHO handover_logic.c:133 (BTS 0 trx 0 ts 1 lchan 0 TCH/F)->(BTS 1 lchan TCH_F) Initiating Handover...
DMSC handover_logic.c:135 SUBSCR_CONN[0x612000000520]{ACTIVE}: Received Event HO_START
DHODEC handover_logic.c:172 (BTS 0 trx 0 arfcn 870 ts 1 lchan 0 TCH/F)->(BTS 1 trx 0 arfcn 871 ts 1 lchan 0 TCH/F) (subscr IMSI:000001) Triggering Handover

===== After =====

DHODEC handover_decision_2.c:1039 (lchan 0.010 TCH_F SPEECH_AMR) (subscr IMSI:000001) MEASUREMENT REPORT (1 neighbors)
DHODEC handover_decision_2.c:1044 (lchan 0.010 TCH_F SPEECH_AMR) (subscr IMSI:000001)   0: arfcn=871 bsic=63 neigh_idx=0 rxlev=30 flags=0
DHODEC handover_decision_2.c:1097 (lchan 0.010 TCH_F SPEECH_AMR) (subscr IMSI:000001) Avg RX level = -110 dBm, +5 dBm AFS bias = -105 dBm; Avg RX quality = -1 (invalid), +0 AFS bias = -1
DHODEC handover_decision_2.c:1122 (lchan 0.010 TCH_F SPEECH_AMR) (subscr IMSI:000001) RX level is TOO LOW: -105 < -100
DHODEC handover_decision_2.c:677 (lchan 0.010 TCH_F SPEECH_AMR)->(BTS 0) (subscr IMSI:000001) RX level -110; TCH/F={free 3 (want 0), [-] not a candidate}; TCH/H={free 4 (want 0), [ABC] good}
DHODEC handover_decision_2.c:671 (lchan 0.010 TCH_F SPEECH_AMR)->(BTS 1) (subscr IMSI:000001) RX level -110 -> -80; TCH/F={free 4 (want 0), [ABC] good}; TCH/H={free 4 (want 0), [ABC] good}
DHODEC handover_decision_2.c:928 (lchan 0.010 TCH_F SPEECH_AMR)->(BTS 1) (subscr IMSI:000001) Best candidate, RX level -80
DHODEC handover_decision_2.c:641 (lchan 0.010 TCH_F SPEECH_AMR)->(BTS 1) (subscr IMSI:000001) Triggering handover to TCH/F, due to low rxlevel
DMSC handover_logic.c:125 SUBSCR_CONN[0x612000000520]{ACTIVE}: Received Event HO_START
DHODEC handover_logic.c:169 (BTS 0 trx 0 arfcn 870 ts 1 lchan 0 TCH_F SPEECH_AMR)->(BTS 1 trx 0 arfcn 871 ts 1 lchan 0 TCH/F) (subscr IMSI:000001) Triggering Handover

Change-Id: If1add9b57a051d32b67a4a08ab47a9655aa9dd17

4 files changed, 81 insertions, 222 deletions

diff --git a/include/osmocom/bsc/handover.h b/include/osmocom/bsc/handover.h
index eb03f6a7b..772ab98e2 100644
--- a/include/osmocom/bsc/handover.h
+++ b/include/osmocom/bsc/handover.h
@@ -12,13 +12,14 @@ struct gsm_subscriber_connection;
 struct gsm_meas_rep mr;
 
 #define LOGPHOLCHANTOLCHAN(old_lchan, new_lchan, level, fmt, args...) \
-	LOGP(DHODEC, level, "(BTS %u trx %u arfcn %u ts %u lchan %u %s)->(BTS %u trx %u arfcn %u ts %u lchan %u %s) (subscr %s) " fmt, \
+	LOGP(DHODEC, level, "(BTS %u trx %u arfcn %u ts %u lchan %u %s %s)->(BTS %u trx %u arfcn %u ts %u lchan %u %s) (subscr %s) " fmt, \
 	     old_lchan->ts->trx->bts->nr, \
 	     old_lchan->ts->trx->nr, \
 	     old_lchan->ts->trx->arfcn, \
 	     old_lchan->ts->nr, \
 	     old_lchan->nr, \
-	     gsm_pchan_name(old_lchan->ts->pchan), \
+	     gsm_lchant_name(old_lchan->type), \
+	     gsm48_chan_mode_name(old_lchan->tch_mode), \
 	     new_lchan->ts->trx->bts->nr, \
 	     new_lchan->ts->trx->nr, \
 	     new_lchan->ts->trx->arfcn, \
diff --git a/src/osmo-bsc/handover_decision.c b/src/osmo-bsc/handover_decision.c
index 887c2993f..0e7902366 100644
--- a/src/osmo-bsc/handover_decision.c
+++ b/src/osmo-bsc/handover_decision.c
@@ -201,7 +201,10 @@ static int attempt_handover(struct gsm_meas_rep *mr)
 	struct gsm_bts *bts = mr->lchan->ts->trx->bts;
 	struct neigh_meas_proc *best_cell = NULL;
 	unsigned int best_better_db = 0;
-	int i, rc;
+	int i;
+
+	if (!ho_get_ho_active(bts->ho))
+		return 0;
 
 	/* find the best cell in this report that is at least RXLEV_HYST
 	 * better than the current serving cell */
@@ -231,28 +234,7 @@ static int attempt_handover(struct gsm_meas_rep *mr)
 	if (!best_cell)
 		return 0;
 
-	LOGP(DHODEC, LOGL_INFO, "%s: Cell on ARFCN %u is better: ",
-		gsm_ts_name(mr->lchan->ts), best_cell->arfcn);
-	if (!ho_get_ho_active(bts->ho)) {
-		LOGPC(DHODEC, LOGL_INFO, "Skipping, Handover disabled\n");
-		return 0;
-	}
-
-	rc = handover_to_arfcn_bsic(mr->lchan, best_cell->arfcn, best_cell->bsic);
-	switch (rc) {
-	case 0:
-		LOGPC(DHODEC, LOGL_INFO, "Starting handover: meas report number %d \n", mr->nr);
-		break;
-	case -ENOSPC:
-		LOGPC(DHODEC, LOGL_INFO, "No channel available\n");
-		break;
-	case -EBUSY:
-		LOGPC(DHODEC, LOGL_INFO, "Handover already active\n");
-		break;
-	default:
-		LOGPC(DHODEC, LOGL_ERROR, "Unknown error\n");
-	}
-	return rc;
+	return handover_to_arfcn_bsic(mr->lchan, best_cell->arfcn, best_cell->bsic);
 }
 
 /* process an already parsed measurement report and decide if we want to
diff --git a/src/osmo-bsc/handover_decision_2.c b/src/osmo-bsc/handover_decision_2.c
index 7ac54df95..e514b6c5f 100644
--- a/src/osmo-bsc/handover_decision_2.c
+++ b/src/osmo-bsc/handover_decision_2.c
@@ -40,22 +40,24 @@
 	LOGP(DHODEC, level, "(BTS %u) " fmt, bts->nr, ## args)
 
 #define LOGPHOLCHAN(lchan, level, fmt, args...) \
-	LOGP(DHODEC, level, "(lchan %u.%u%u%u %s) (subscr %s) " fmt, \
+	LOGP(DHODEC, level, "(lchan %u.%u%u%u %s %s) (subscr %s) " fmt, \
 	     lchan->ts->trx->bts->nr, \
 	     lchan->ts->trx->nr, \
 	     lchan->ts->nr, \
 	     lchan->nr, \
-	     gsm_pchan_name(lchan->ts->pchan), \
+	     gsm_lchant_name(lchan->type), \
+	     gsm48_chan_mode_name(lchan->tch_mode), \
 	     bsc_subscr_name(lchan->conn? lchan->conn->bsub : NULL), \
 	     ## args)
 
 #define LOGPHOLCHANTOBTS(lchan, new_bts, level, fmt, args...) \
-	LOGP(DHODEC, level, "(lchan %u.%u%u%u %s)->(BTS %u) (subscr %s) " fmt, \
+	LOGP(DHODEC, level, "(lchan %u.%u%u%u %s %s)->(BTS %u) (subscr %s) " fmt, \
 	     lchan->ts->trx->bts->nr, \
 	     lchan->ts->trx->nr, \
 	     lchan->ts->nr, \
 	     lchan->nr, \
-	     gsm_pchan_name(lchan->ts->pchan), \
+	     gsm_lchant_name(lchan->type), \
+	     gsm48_chan_mode_name(lchan->tch_mode), \
 	     new_bts->nr, \
 	     bsc_subscr_name(lchan->conn? lchan->conn->bsub : NULL), \
 	     ## args)
@@ -257,13 +259,9 @@ static void process_meas_neigh(struct gsm_meas_rep *mr)
 		if (mrc) {
 			nmp->rxlev[idx] = mrc->rxlev;
 			nmp->last_seen_nr = mr->nr;
-			LOGPHOLCHAN(mr->lchan, LOGL_DEBUG, "neigh %u rxlev=%d last_seen_nr=%u\n",
-				    nmp->arfcn, mrc->rxlev, nmp->last_seen_nr);
 			mrc->flags |= MRC_F_PROCESSED;
 		} else {
 			nmp->rxlev[idx] = 0;
-			LOGPHOLCHAN(mr->lchan, LOGL_DEBUG, "neigh %u not in report (last_seen_nr=%u)\n",
-				    nmp->arfcn, nmp->last_seen_nr);
 		}
 		nmp->rxlev_cnt++;
 	}
@@ -308,11 +306,8 @@ static bool codec_type_is_supported(struct gsm_subscriber_connection *conn,
 	}
 
 	for (i = 0; i < clist->len; i++) {
-		if (clist->codec[i].type == type) {
-			LOGPHOLCHAN(conn->lchan, LOGL_DEBUG, "%s supported\n",
-				    gsm0808_speech_codec_type_name(type));
+		if (clist->codec[i].type == type)
 			return true;
-		}
 	}
 	LOGPHOLCHAN(conn->lchan, LOGL_DEBUG, "Codec not supported by MS or not allowed by MSC: %s\n",
 		    gsm0808_speech_codec_type_name(type));
@@ -402,10 +397,6 @@ static uint8_t check_requirements(struct gsm_lchan *lchan, struct gsm_bts *bts,
 		return 0;
 	}
 
-	LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG, "tch_mode='%s' type='%s'\n",
-			 get_value_string(gsm48_chan_mode_names, lchan->tch_mode),
-			 gsm_lchant_name(lchan->type));
-
 	/* compatibility check for codecs.
 	 * if so, the candidates for full rate and half rate are selected */
 	switch (lchan->tch_mode) {
@@ -413,9 +404,6 @@ static uint8_t check_requirements(struct gsm_lchan *lchan, struct gsm_bts *bts,
 		switch (lchan->type) {
 		case GSM_LCHAN_TCH_F: /* mandatory */
 			requirement |= REQUIREMENT_A_TCHF;
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG, "tch_mode='%s' type='%s' supported\n",
-					 get_value_string(gsm48_chan_mode_names, lchan->tch_mode),
-					 gsm_lchant_name(lchan->type));
 			break;
 		case GSM_LCHAN_TCH_H:
 			if (!bts->codec.hr) {
@@ -485,13 +473,9 @@ static uint8_t check_requirements(struct gsm_lchan *lchan, struct gsm_bts *bts,
 	if (bts == current_bts) {
 		switch (lchan->type) {
 		case GSM_LCHAN_TCH_F:
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "removing TCH/F, already on TCH/F in this cell\n");
 			requirement &= ~(REQUIREMENT_A_TCHF);
 			break;
 		case GSM_LCHAN_TCH_H:
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "removing TCH/H, already on TCH/H in this cell\n");
 			requirement &= ~(REQUIREMENT_A_TCHH);
 			break;
 		default:
@@ -558,24 +542,12 @@ static uint8_t check_requirements(struct gsm_lchan *lchan, struct gsm_bts *bts,
 	/* the minimum free timeslots that are defined for this cell must
 	 * be maintained _after_ handover/assignment */
 	if (requirement & REQUIREMENT_A_TCHF) {
-		if (tchf_count - 1 >= ho_get_hodec2_tchf_min_slots(bts->ho)) {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/F would not be congested after HO\n");
+		if (tchf_count - 1 >= ho_get_hodec2_tchf_min_slots(bts->ho))
 			requirement |= REQUIREMENT_B_TCHF;
-		} else {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/F would be congested after HO\n");
-		}
 	}
 	if (requirement & REQUIREMENT_A_TCHH) {
-		if (tchh_count - 1 >= ho_get_hodec2_tchh_min_slots(bts->ho)) {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/H would not be congested after HO\n");
+		if (tchh_count - 1 >= ho_get_hodec2_tchh_min_slots(bts->ho))
 			requirement |= REQUIREMENT_B_TCHH;
-		} else {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/H would be congested after HO\n");
-		}
 	}
 
 	/* Requirement C */
@@ -584,30 +556,16 @@ static uint8_t check_requirements(struct gsm_lchan *lchan, struct gsm_bts *bts,
 	 * free slots of the current cell _after_ handover/assignment */
 	count = bts_count_free_ts(current_bts,
 				  (lchan->type == GSM_LCHAN_TCH_H) ?
-				  	GSM_PCHAN_TCH_H : GSM_PCHAN_TCH_F);
+				   GSM_PCHAN_TCH_H : GSM_PCHAN_TCH_F);
 	if (requirement & REQUIREMENT_A_TCHF) {
-		if (tchf_count - 1 >= count + 1) {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/F would be less congested in target than source cell after HO\n");
+		if (tchf_count - 1 >= count + 1)
 			requirement |= REQUIREMENT_C_TCHF;
-		} else {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/F would not be less congested in target than source cell after HO\n");
-		}
 	}
 	if (requirement & REQUIREMENT_A_TCHH) {
-		if (tchh_count - 1 >= count + 1) {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/H would be less congested in target than source cell after HO\n");
+		if (tchh_count - 1 >= count + 1)
 			requirement |= REQUIREMENT_C_TCHH;
-		} else {
-			LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG,
-					 "TCH/H would not be less congested in target than source cell after HO\n");
-		}
 	}
 
-	LOGPHOLCHANTOBTS(lchan, bts, LOGL_DEBUG, "requirements=0x%x\n", requirement);
-
 	/* return mask of fulfilled requirements */
 	return requirement;
 }
@@ -619,11 +577,6 @@ static int trigger_handover_or_assignment(struct gsm_lchan *lchan, struct gsm_bt
 	int afs_bias = 0;
 	bool full_rate = false;
 
-	if (current_bts == new_bts)
-		LOGPHOLCHAN(lchan, LOGL_NOTICE, "Triggering Assignment\n");
-	else
-		LOGPHOLCHANTOBTS(lchan, new_bts, LOGL_NOTICE, "Triggering Handover\n");
-
 	/* afs_bias becomes > 0, if AFS is used and is improved */
 	if (lchan->tch_mode == GSM48_CMODE_SPEECH_AMR)
 		afs_bias = ho_get_hodec2_afs_bias_rxlev(new_bts->ho);
@@ -682,7 +635,7 @@ static int trigger_handover_or_assignment(struct gsm_lchan *lchan, struct gsm_bt
 			    full_rate ? "TCH/F" : "TCH/H",
 			    ho_reason_name(global_ho_reason));
 	else
-		LOGPHOLCHANTOBTS(lchan, new_bts, LOGL_NOTICE,
+		LOGPHOLCHANTOBTS(lchan, new_bts, LOGL_INFO,
 				 "Triggering handover to %s, due to %s\n",
 				 full_rate ? "TCH/F" : "TCH/H",
 				 ho_reason_name(global_ho_reason));
@@ -692,71 +645,36 @@ static int trigger_handover_or_assignment(struct gsm_lchan *lchan, struct gsm_bt
 }
 
 /* debug collected candidates */
-static inline void debug_candidate(struct ho_candidate *candidate,
-	int neighbor, int8_t rxlev, int tchf_count, int tchh_count)
+static inline void debug_candidate(struct gsm_lchan *lchan, struct ho_candidate *candidate,
+	struct gsm_bts *neighbor, int8_t rxlev, int tchf_count, int tchh_count)
 {
-	if (neighbor)
-		LOGP(DHODEC, LOGL_DEBUG, " - neighbor BTS %d, RX level "
-			"%d -> %d\n", candidate->bts->nr, rxlev2dbm(rxlev),
-			rxlev2dbm(candidate->avg));
-	else
-		LOGP(DHODEC, LOGL_DEBUG, " - current BTS %d, RX level %d\n",
-			candidate->bts->nr, rxlev2dbm(candidate->avg));
-
-	LOGP(DHODEC, LOGL_DEBUG, "   o free TCH/F slots %d, minimum required "
-		"%d\n", tchf_count, ho_get_hodec2_tchf_min_slots(candidate->bts->ho));
-	LOGP(DHODEC, LOGL_DEBUG, "   o free TCH/H slots %d, minimum required "
-		"%d\n", tchh_count, ho_get_hodec2_tchh_min_slots(candidate->bts->ho));
+#define HO_CANDIDATE_FMT(tchx, TCHX) "TCH/" #TCHX "={free %d (want %d), [%s%s%s]%s}"
+#define HO_CANDIDATE_ARGS(tchx, TCHX) \
+	     tch##tchx##_count, ho_get_hodec2_tch##tchx##_min_slots(candidate->bts->ho), \
+	     candidate->requirements & REQUIREMENT_A_TCH##TCHX ? "A" : \
+		(candidate->requirements & REQUIREMENT_TCH##TCHX##_MASK) == 0? "-" : "", \
+	     candidate->requirements & REQUIREMENT_B_TCH##TCHX ? "B" : "", \
+	     candidate->requirements & REQUIREMENT_B_TCH##TCHX ? "C" : "", \
+	     (candidate->requirements & REQUIREMENT_TCH##TCHX##_MASK) == 0 ? " not a candidate" : \
+	       ((candidate->requirements & REQUIREMENT_TCH##TCHX##_MASK) == REQUIREMENT_A_TCH##TCHX ? \
+	        " more congestion" : \
+		(candidate->requirements & REQUIREMENT_B_TCH##TCHX ? \
+		 " good" : \
+		  /* now has to be candidate->requirements & REQUIREMENT_C_TCHX != 0: */ \
+		  " less-or-equal congestion"))
 
-	if ((candidate->requirements & REQUIREMENT_TCHF_MASK))
-		LOGP(DHODEC, LOGL_DEBUG, "   o requirement ");
-	else
-		LOGP(DHODEC, LOGL_DEBUG, "   o no requirement ");
-	if ((candidate->requirements & REQUIREMENT_A_TCHF))
-		LOGPC(DHODEC, LOGL_DEBUG, "A ");
-	if ((candidate->requirements & REQUIREMENT_B_TCHF))
-		LOGPC(DHODEC, LOGL_DEBUG, "B ");
-	if ((candidate->requirements & REQUIREMENT_C_TCHF))
-		LOGPC(DHODEC, LOGL_DEBUG, "C ");
-	LOGPC(DHODEC, LOGL_DEBUG, "fulfilled for TCHF");
-	if (!(candidate->requirements & REQUIREMENT_TCHF_MASK)) /* nothing */
-		LOGPC(DHODEC, LOGL_DEBUG, " (no %s possible)\n",
-			(neighbor) ? "handover" : "assignment");
-	else if ((candidate->requirements & REQUIREMENT_TCHF_MASK)
-					== REQUIREMENT_A_TCHF) /* only A */
-		LOGPC(DHODEC, LOGL_DEBUG, " (more congestion after %s)\n",
-			(neighbor) ? "handover" : "assignment");
-	else if ((candidate->requirements & REQUIREMENT_B_TCHF)) /* B incl. */
-		LOGPC(DHODEC, LOGL_DEBUG, " (not congested after %s)\n",
-			(neighbor) ? "handover" : "assignment");
-	else /* so it must include C */
-		LOGPC(DHODEC, LOGL_DEBUG, " (less or equally congested after "
-			"%s)\n", (neighbor) ? "handover" : "assignment");
-
-	if ((candidate->requirements & REQUIREMENT_TCHH_MASK))
-		LOGP(DHODEC, LOGL_DEBUG, "   o requirement ");
+	if (neighbor)
+		LOGPHOLCHANTOBTS(lchan, neighbor, LOGL_DEBUG,
+		     "RX level %d -> %d; "
+		     HO_CANDIDATE_FMT(f, F) "; " HO_CANDIDATE_FMT(h, H) "\n",
+		     rxlev2dbm(rxlev), rxlev2dbm(candidate->avg),
+		     HO_CANDIDATE_ARGS(f, F), HO_CANDIDATE_ARGS(h, H));
 	else
-		LOGP(DHODEC, LOGL_DEBUG, "   o no requirement ");
-	if ((candidate->requirements & REQUIREMENT_A_TCHH))
-		LOGPC(DHODEC, LOGL_DEBUG, "A ");
-	if ((candidate->requirements & REQUIREMENT_B_TCHH))
-		LOGPC(DHODEC, LOGL_DEBUG, "B ");
-	if ((candidate->requirements & REQUIREMENT_C_TCHH))
-		LOGPC(DHODEC, LOGL_DEBUG, "C ");
-	LOGPC(DHODEC, LOGL_DEBUG, "fulfilled for TCHH");
-	if (!(candidate->requirements & REQUIREMENT_TCHH_MASK)) /* nothing */
-		LOGPC(DHODEC, LOGL_DEBUG, " (no %s possible)\n",
-			(neighbor) ? "handover" : "assignment");
-	else if ((candidate->requirements & REQUIREMENT_TCHH_MASK)
-					== REQUIREMENT_A_TCHH) /* only A */
-		LOGPC(DHODEC, LOGL_DEBUG, " (more congestion after %s)\n",
-			(neighbor) ? "handover" : "assignment");
-	else if ((candidate->requirements & REQUIREMENT_B_TCHH)) /* B incl. */
-		LOGPC(DHODEC, LOGL_DEBUG, " (not congested after %s)\n",
-			(neighbor) ? "handover" : "assignment");
-	else /* so it must include C */
-		LOGPC(DHODEC, LOGL_DEBUG, " (less or equally congested after "
-			"%s)\n", (neighbor) ? "handover" : "assignment");
+		LOGPHOLCHANTOBTS(lchan, lchan->ts->trx->bts, LOGL_DEBUG,
+		     "RX level %d; "
+		     HO_CANDIDATE_FMT(f, F) "; " HO_CANDIDATE_FMT(h, H) "\n",
+		     rxlev2dbm(candidate->avg),
+		     HO_CANDIDATE_ARGS(f, F), HO_CANDIDATE_ARGS(h, H));
 }
 
 /* add candidate for re-assignment within the current cell */
@@ -775,7 +693,7 @@ static void collect_assignment_candidate(struct gsm_lchan *lchan, struct ho_cand
 	c->bts = bts;
 	c->requirements = check_requirements(lchan, bts, tchf_count, tchh_count);
 	c->avg = av_rxlev;
-	debug_candidate(c, 0, 0, tchf_count, tchh_count);
+	debug_candidate(lchan, c, NULL, 0, tchf_count, tchh_count);
 	(*candidates)++;
 }
 
@@ -855,7 +773,7 @@ static void collect_handover_candidate(struct gsm_lchan *lchan, struct neigh_mea
 	c->requirements = check_requirements(lchan, neighbor_bts, tchf_count,
 					     tchh_count);
 	c->avg = avg;
-	debug_candidate(c, 1, av_rxlev, tchf_count, tchh_count);
+	debug_candidate(lchan, c, neighbor_bts, av_rxlev, tchf_count, tchh_count);
 	(*candidates)++;
 }
 
@@ -865,14 +783,12 @@ static void collect_candidates_for_lchan(struct gsm_lchan *lchan,
 {
 	struct gsm_bts *bts = lchan->ts->trx->bts;
 	int av_rxlev;
-	unsigned int candidates_was;
 	bool assignment;
 	bool handover;
 	int neighbors_count = 0;
 	unsigned int rxlev_avg_win = ho_get_hodec2_rxlev_avg_win(bts->ho);
 
 	OSMO_ASSERT(candidates);
-	candidates_was = *candidates;
 
 	/* caculate average rxlev for this cell over the window */
 	av_rxlev = get_meas_rep_avg(lchan,
@@ -893,11 +809,6 @@ static void collect_candidates_for_lchan(struct gsm_lchan *lchan,
 	assignment = ho_get_hodec2_as_active(bts->ho);
 	handover = ho_get_ho_active(bts->ho);
 
-	LOGPHOLCHAN(lchan, LOGL_DEBUG, "Collecting candidates for%s%s%s\n",
-		    assignment ? " Assignment" : "",
-		    assignment && handover ? " and" : "",
-		    handover ? " Handover" : "");
-
 	if (assignment)
 		collect_assignment_candidate(lchan, clist, candidates, av_rxlev);
 
@@ -909,9 +820,6 @@ static void collect_candidates_for_lchan(struct gsm_lchan *lchan,
 						   include_weaker_rxlev, av_rxlev, &neighbors_count);
 		}
 	}
-
-	LOGPHOLCHAN(lchan, LOGL_DEBUG, "adding %u candidates from %u neighbors, total %u\n",
-		    *candidates - candidates_was, neighbors_count, *candidates);
 }
 
 /*
@@ -1155,8 +1063,6 @@ static void on_measurement_report(struct gsm_meas_rep *mr)
 		return;
 	}
 
-	LOGPHOLCHAN(lchan, LOGL_DEBUG, "HODEC2: evaluating measurement report\n");
-
 	/* get average levels. if not enought measurements yet, value is < 0 */
 	av_rxlev = get_meas_rep_avg(lchan,
 				    ho_get_hodec2_full_tdma(bts->ho) ?
@@ -1170,34 +1076,29 @@ static void on_measurement_report(struct gsm_meas_rep *mr)
 		LOGPHOLCHAN(lchan, LOGL_INFO, "Skipping, Not enough recent measurements\n");
 		return;
 	}
-	if (av_rxlev >= 0) {
-		LOGPHOLCHAN(lchan, LOGL_DEBUG, "Measurement report: average RX level = %d\n",
-			    rxlev2dbm(av_rxlev));
-	}
-	if (av_rxqual >= 0) {
-		LOGPHOLCHAN(lchan, LOGL_DEBUG, "Measurement report: average RX quality = %d\n",
-			    av_rxqual);
-	}
 
 	/* improve levels in case of AFS, if defined */
 	if (lchan->type == GSM_LCHAN_TCH_F
 	 && lchan->tch_mode == GSM48_CMODE_SPEECH_AMR) {
+		int av_rxlev_was = av_rxlev;
+		int av_rxqual_was = av_rxqual;
 		int rxlev_bias = ho_get_hodec2_afs_bias_rxlev(bts->ho);
 		int rxqual_bias = ho_get_hodec2_afs_bias_rxqual(bts->ho);
-		if (av_rxlev >= 0 && rxlev_bias) {
-			int imp = av_rxlev + rxlev_bias;
-			LOGPHOLCHAN(lchan, LOGL_INFO, "Virtually improving RX level from %d to %d,"
-				    " due to AFS bias\n", rxlev2dbm(av_rxlev), rxlev2dbm(imp));
-			av_rxlev = imp;
-		}
-		if (av_rxqual >= 0 && rxqual_bias) {
-			int imp = av_rxqual - rxqual_bias;
-			if (imp < 0)
-				imp = 0;
-			LOGPHOLCHAN(lchan, LOGL_INFO, "Virtually improving RX quality from %d to %d,"
-				    " due to AFS bias\n", rxlev2dbm(av_rxqual), rxlev2dbm(imp));
-			av_rxqual = imp;
-		}
+		if (av_rxlev >= 0)
+			av_rxlev = av_rxlev + rxlev_bias;
+		if (av_rxqual >= 0)
+			av_rxqual = OSMO_MAX(0, av_rxqual - rxqual_bias);
+
+		LOGPHOLCHAN(lchan, LOGL_DEBUG,
+			    "Avg RX level = %d dBm, %+d dBm AFS bias = %d dBm;"
+			    " Avg RX quality = %d%s, %+d AFS bias = %d\n",
+			    rxlev2dbm(av_rxlev_was), rxlev_bias, rxlev2dbm(av_rxlev),
+			    OSMO_MAX(-1, av_rxqual_was), av_rxqual_was < 0 ? " (invalid)" : "",
+			    -rxqual_bias, OSMO_MAX(-1, av_rxqual));
+	} else {
+		LOGPHOLCHAN(lchan, LOGL_DEBUG, "Avg RX level = %d dBm; Avg RX quality = %d%s\n",
+			    rxlev2dbm(av_rxlev),
+			    OSMO_MAX(-1, av_rxqual), av_rxqual < 0 ? " (invalid)" : "");
 	}
 
 	/* Bad Quality */
@@ -1217,7 +1118,8 @@ static void on_measurement_report(struct gsm_meas_rep *mr)
 	/* Low Level */
 	if (av_rxlev >= 0 && rxlev2dbm(av_rxlev) < ho_get_hodec2_min_rxlev(bts->ho)) {
 		global_ho_reason = HO_REASON_LOW_RXLEVEL;
-		LOGPHOLCHAN(lchan, LOGL_INFO, "Attempting handover/assignment due to low rxlev\n");
+		LOGPHOLCHAN(lchan, LOGL_NOTICE, "RX level is TOO LOW: %d < %d\n",
+			    rxlev2dbm(av_rxlev), ho_get_hodec2_min_rxlev(bts->ho));
 		find_alternative_lchan(lchan, true);
 		return;
 	}
@@ -1226,7 +1128,8 @@ static void on_measurement_report(struct gsm_meas_rep *mr)
 	if (lchan->meas_rep_count > 0
 	    && lchan->rqd_ta > ho_get_hodec2_max_distance(bts->ho)) {
 		global_ho_reason = HO_REASON_MAX_DISTANCE;
-		LOGPHOLCHAN(lchan, LOGL_INFO, "Attempting handover due to high TA\n");
+		LOGPHOLCHAN(lchan, LOGL_NOTICE, "TA is TOO HIGH: %u > %d\n",
+			    lchan->rqd_ta, ho_get_hodec2_max_distance(bts->ho));
 		/* start penalty timer to prevent comming back too
 		 * early. it must be started before selecting a better cell,
 		 * so there is no assignment selected, due to running
@@ -1242,7 +1145,6 @@ static void on_measurement_report(struct gsm_meas_rep *mr)
 
 	/* try handover to a better cell */
 	if (av_rxlev >= 0 && (mr->nr % pwr_interval) == 0) {
-		LOGPHOLCHAN(lchan, LOGL_INFO, "Looking whether a cell has better RXLEV\n");
 		global_ho_reason = HO_REASON_BETTER_CELL;
 		find_alternative_lchan(lchan, false);
 	}
@@ -1439,12 +1341,10 @@ next_b1:
 	/* perform handover, if there is a candidate */
 	if (best_cand) {
 		any_ho = 1;
-		LOGPHOLCHAN(best_cand->lchan, LOGL_INFO,
-			    "Best candidate BTS %u (RX level %d) without congestion found\n",
-			    best_cand->bts->nr, rxlev2dbm(best_cand->avg));
-		if (is_improved)
-			LOGP(DHODEC, LOGL_INFO, "(is improved due to "
-				"AHS -> AFS)\n");
+		LOGPHOLCHAN(best_cand->lchan, LOGL_DEBUG,
+			    "Best candidate BTS %u (RX level %d%s) without congestion found\n",
+			    best_cand->bts->nr, rxlev2dbm(best_cand->avg),
+			    is_improved ? ", RX quality improved by AHS->AFS" : "");
 		trigger_handover_or_assignment(best_cand->lchan, best_cand->bts,
 			best_cand->requirements & REQUIREMENT_B_MASK);
 #if 0
@@ -1468,9 +1368,6 @@ next_b1:
 		goto exit;
 	}
 
-	LOGPHOBTS(bts, LOGL_DEBUG, "Did not find a best candidate that fulfills requirement B"
-		  " (omitting change from AHS to AFS)\n");
-
 #if 0
 next_b2:
 #endif
@@ -1504,8 +1401,6 @@ next_b2:
 				is_improved = 1;
 			} else
 				is_improved = 0;
-			LOGP(DHODEC, LOGL_DEBUG, "candidate %d: avg=%d worst_avg_db=%d\n", i, avg,
-			     worst_avg_db);
 			if (avg < worst_avg_db) {
 				worst_cand = &clist[i];
 				worst_avg_db = avg;
@@ -1517,11 +1412,9 @@ next_b2:
 	if (worst_cand) {
 		any_ho = 1;
 		LOGP(DHODEC, LOGL_INFO, "Worst candidate for assignment "
-			"(RX level %d) from TCH/H -> TCH/F without congestion "
-			"found\n", rxlev2dbm(worst_cand->avg));
-		if (is_improved)
-			LOGP(DHODEC, LOGL_INFO, "(is improved due to "
-				"AHS -> AFS)\n");
+			"(RX level %d%s) from TCH/H -> TCH/F without congestion "
+			"found\n", rxlev2dbm(worst_cand->avg),
+			is_improved ? ", RX quality improved by AHS->AFS" : "");
 		trigger_handover_or_assignment(worst_cand->lchan,
 			worst_cand->bts,
 			worst_cand->requirements & REQUIREMENT_B_MASK);
@@ -1543,9 +1436,6 @@ next_b2:
 		goto exit;
 	}
 
-	LOGPHOBTS(bts, LOGL_DEBUG, "Did not find a worst candidate that fulfills requirement B,"
-		  " selecting candidates that change from AHS to AFS only\n");
-
 #if 0
 next_c1:
 #endif
@@ -1584,7 +1474,6 @@ next_c1:
 			is_improved = 1;
 		} else
 			is_improved = 0;
-		LOGP(DHODEC, LOGL_DEBUG, "candidate %d: avg=%d best_avg_db=%d\n", i, avg, best_avg_db);
 		if (avg > best_avg_db) {
 			best_cand = &clist[i];
 			best_avg_db = avg;
@@ -1672,11 +1561,9 @@ next_c2:
 	if (worst_cand) {
 		any_ho = 1;
 		LOGP(DHODEC, LOGL_INFO, "Worst candidate for assignment "
-			"(RX level %d) from TCH/H -> TCH/F with less or equal "
-			"congestion found\n", rxlev2dbm(worst_cand->avg));
-		if (is_improved)
-			LOGP(DHODEC, LOGL_INFO, "(is improved due to "
-				"AHS -> AFS)\n");
+			"(RX level %d%s) from TCH/H -> TCH/F with less or equal "
+			"congestion found\n", rxlev2dbm(worst_cand->avg),
+			is_improved ? ", RX quality improved by AHS->AFS" : "");
 		trigger_handover_or_assignment(worst_cand->lchan,
 			worst_cand->bts,
 			worst_cand->requirements & REQUIREMENT_C_MASK);
diff --git a/src/osmo-bsc/handover_logic.c b/src/osmo-bsc/handover_logic.c
index 064615cbc..509de533b 100644
--- a/src/osmo-bsc/handover_logic.c
+++ b/src/osmo-bsc/handover_logic.c
@@ -122,17 +122,6 @@ int bsc_handover_start(enum hodec_id from_hodec_id, struct gsm_lchan *old_lchan,
 	llist_add(&ho->list, &bsc_handovers);
 
 	conn->ho = ho;
-
-	DEBUGP(DHO, "(BTS %u trx %u ts %u lchan %u %s)->(BTS %u lchan %s) Initiating %s...\n",
-	       old_lchan->ts->trx->bts->nr,
-	       old_lchan->ts->trx->nr,
-	       old_lchan->ts->nr,
-	       old_lchan->nr,
-	       gsm_pchan_name(old_lchan->ts->pchan),
-	       new_bts->nr,
-	       gsm_lchant_name(new_lchan_type),
-	       do_assignment ? "Assignment" : "Handover");
-
 	rc = osmo_fsm_inst_dispatch(conn->fi, GSCON_EV_HO_START, NULL);
 
 	if (rc < 0) {