add/improve various logging around dyn ts

This logging turned up while I was debugging dynamic timeslots:
- OML Set Channel Attributes logging.
- a specific dyn TS pchan error.
- show pchan and lchan types on CHAN ACT ACK and REL ACK logging.
- on RSL message Rx, log the current pchan kind in detail, using
  gsm_ts_and_pchan_name(). This logs the underlying pchan as well as the
  current pchan mode a dyn TS is in.
- move 2 dyn TS logging from DL1C to DRSL, where all the other dyn ts logging
  is.

Change-Id: Ia89c134060e85f7065afd5642d1c541c65dd25ea

2 files changed, 22 insertions, 10 deletions

diff --git a/src/common/oml.c b/src/common/oml.c
index 89db9cf5..41debc1b 100644
--- a/src/common/oml.c
+++ b/src/common/oml.c
@@ -950,6 +950,7 @@ static int oml_rx_set_chan_attr(struct gsm_bts_trx_ts *ts, struct msgb *msg)
 	/* Call into BTS driver to check attribute values */
 	rc = bts_model_check_oml(bts, foh->msg_type, ts->mo.nm_attr, tp_merged, ts);
 	if (rc < 0) {
+		LOGP(DOML, LOGL_ERROR, "SET CHAN ATTR: invalid attribute value, rc=%d\n", rc);
 		talloc_free(tp_merged);
 		/* Send NACK */
 		return oml_fom_ack_nack(msg, -rc);
@@ -965,6 +966,9 @@ static int oml_rx_set_chan_attr(struct gsm_bts_trx_ts *ts, struct msgb *msg)
 		ts->pchan = abis_nm_pchan4chcomb(comb);
 		rc = conf_lchans(ts);
 		if (rc < 0) {
+			LOGP(DOML, LOGL_ERROR, "SET CHAN ATTR: invalid Chan Comb 0x%x"
+			     " (pchan=%s, conf_lchans()->%d)\n",
+			     comb, gsm_pchan_name(ts->pchan), rc);
 			talloc_free(tp_merged);
 			/* Send NACK */
 			return oml_fom_ack_nack(msg, -rc);
@@ -980,8 +984,8 @@ static int oml_rx_set_chan_attr(struct gsm_bts_trx_ts *ts, struct msgb *msg)
 		/* If there is no TSC specified, use the BCC */
 		ts->tsc = BSIC2BCC(bts->bsic);
 	}
-	LOGP(DOML, LOGL_INFO, "%s SET CHAN ATTR (TSC = %u)\n",
-		gsm_abis_mo_name(&ts->mo), ts->tsc);
+	LOGP(DOML, LOGL_INFO, "%s SET CHAN ATTR (TSC=%u pchan=%s)\n",
+		gsm_abis_mo_name(&ts->mo), ts->tsc, gsm_pchan_name(ts->pchan));
 
 	/* call into BTS driver to apply new attributes to hardware */
 	return bts_model_apply_oml(bts, msg, tp_merged, NM_OC_CHANNEL, ts);
diff --git a/src/common/rsl.c b/src/common/rsl.c
index 902b68f8..8a1a232f 100644
--- a/src/common/rsl.c
+++ b/src/common/rsl.c
@@ -683,7 +683,9 @@ int rsl_tx_rf_rel_ack(struct gsm_lchan *lchan)
 		return 0;
 	}
 
-	LOGP(DRSL, LOGL_NOTICE, "%s Tx RF CHAN REL ACK\n", gsm_lchan_name(lchan));
+	LOGP(DRSL, LOGL_NOTICE, "%s (ss=%d) %s Tx CHAN REL ACK\n",
+	     gsm_ts_and_pchan_name(lchan->ts), lchan->nr,
+	     gsm_lchant_name(lchan->type));
 
 	/*
 	 * Free the LAPDm resources now that the BTS
@@ -702,7 +704,9 @@ static int rsl_tx_chan_act_ack(struct gsm_lchan *lchan)
 	uint8_t chan_nr = gsm_lchan2chan_nr(lchan);
 	uint8_t ie[2];
 
-	LOGP(DRSL, LOGL_NOTICE, "%s Tx CHAN ACT ACK\n", gsm_lchan_name(lchan));
+	LOGP(DRSL, LOGL_NOTICE, "%s (ss=%d) %s Tx CHAN ACT ACK\n",
+	     gsm_ts_and_pchan_name(lchan->ts), lchan->nr,
+	     gsm_lchant_name(lchan->type));
 
 	msg = rsl_msgb_alloc(sizeof(struct abis_rsl_dchan_hdr));
 	if (!msg)
@@ -987,6 +991,9 @@ static int rsl_rx_chan_activ(struct msgb *msg)
 		}
 	}
 
+	LOGP(DRSL, LOGL_DEBUG, "%s: rx Channel Activation in state: %s.\n",
+	     gsm_lchan_name(lchan), gsm_lchans_name(lchan->state));
+
 	/* Initialize channel defaults */
 	lchan->ms_power = ms_pwr_ctl_lvl(lchan->ts->trx->bts->band, 0);
 	lchan->ms_power_ctrl.current = lchan->ms_power;
@@ -2106,7 +2113,7 @@ static void rsl_rx_dyn_pdch(struct msgb *msg, bool pdch_act)
 	if (ts->flags & TS_F_PDCH_PENDING_MASK) {
 		/* Only one of the pending flags should ever be set at the same
 		 * time, but just log both in case both should be set. */
-		LOGP(DL1C, LOGL_ERROR,
+		LOGP(DRSL, LOGL_ERROR,
 		     "%s Request to PDCH %s, but PDCH%s%s is still pending\n",
 		     gsm_lchan_name(lchan), pdch_act? "ACT" : "DEACT",
 		     (ts->flags & TS_F_PDCH_ACT_PENDING)? " ACT" : "",
@@ -2212,8 +2219,8 @@ static void osmo_dyn_ts_disconnected(struct gsm_bts_trx_ts *ts)
 		break;
 	default:
 		LOGP(DRSL, LOGL_ERROR,
-		     "%s Dyn TS disconnected, but invalid desired pchan",
-		     gsm_ts_and_pchan_name(ts));
+		     "%s Dyn TS disconnected, but invalid desired pchan: %s\n",
+		     gsm_ts_and_pchan_name(ts), gsm_pchan_name(ts->dyn.pchan_want));
 		ts->dyn.pchan_want = GSM_PCHAN_NONE;
 		/* TODO: how would this recover? */
 		return;
@@ -2351,7 +2358,7 @@ void ipacc_dyn_pdch_complete(struct gsm_bts_trx_ts *ts, int rc)
 		ts->flags |= TS_F_PDCH_ACTIVE;
 	else
 		ts->flags &= ~TS_F_PDCH_ACTIVE;
-	DEBUGP(DL1C, "%s %s switched to %s mode (ts->flags == %x)\n",
+	DEBUGP(DRSL, "%s %s switched to %s mode (ts->flags == %x)\n",
 	       gsm_lchan_name(ts->lchan), gsm_pchan_name(ts->pchan),
 	       pdch_act? "PDCH" : "TCH/F", ts->flags);
 
@@ -2697,8 +2704,9 @@ static int rsl_rx_dchan(struct gsm_bts_trx *trx, struct msgb *msg)
 		return rsl_reject_unknown_lchan(msg);
 	}
 
-	LOGP(DRSL, LOGL_INFO, "%s Rx RSL %s\n", gsm_lchan_name(msg->lchan),
-		rsl_or_ipac_msg_name(dch->c.msg_type));
+	LOGP(DRSL, LOGL_INFO, "%s ss=%d Rx RSL %s\n",
+	     gsm_ts_and_pchan_name(msg->lchan->ts), msg->lchan->nr,
+	     rsl_or_ipac_msg_name(dch->c.msg_type));
 
 	switch (dch->c.msg_type) {
 	case RSL_MT_CHAN_ACTIV: