s390/net/ctcm: message cleanup

Cc: Martin Schwidefsky <schwidefsky@de.ibm.com>
Signed-off-by: Peter Tiedemann <ptiedem@de.ibm.com>
Signed-off-by: Ursula Braun <ursula.braun@de.ibm.com>
Signed-off-by: Jeff Garzik <jgarzik@redhat.com>

1 files changed, 170 insertions, 232 deletions

diff --git a/drivers/s390/net/ctcm_fsms.c b/drivers/s390/net/ctcm_fsms.c
index 7e6bd387f4d8..0b4e6253abe4 100644
--- a/drivers/s390/net/ctcm_fsms.c
+++ b/drivers/s390/net/ctcm_fsms.c
@@ -190,7 +190,8 @@ static void ctcmpc_chx_send_sweep(fsm_instance *fsm, int event, void *arg);
 void ctcm_ccw_check_rc(struct channel *ch, int rc, char *msg)
 {
 	CTCM_DBF_TEXT_(ERROR, CTC_DBF_ERROR,
-			"ccw error %s (%s): %04x\n", ch->id, msg, rc);
+			"%s(%s): %s: %04x\n",
+				CTCM_FUNTAIL, ch->id, msg, rc);
 	switch (rc) {
 	case -EBUSY:
 		ctcm_pr_warn("%s (%s): Busy !\n", ch->id, msg);
@@ -212,7 +213,7 @@ void ctcm_purge_skb_queue(struct sk_buff_head *q)
 {
 	struct sk_buff *skb;
 
-	CTCM_DBF_TEXT(TRACE, 3, __FUNCTION__);
+	CTCM_DBF_TEXT(TRACE, CTC_DBF_DEBUG, __func__);
 
 	while ((skb = skb_dequeue(q))) {
 		atomic_dec(&skb->users);
@@ -251,6 +252,8 @@ static void chx_txdone(fsm_instance *fi, int event, void *arg)
 	unsigned long duration;
 	struct timespec done_stamp = current_kernel_time(); /* xtime */
 
+	CTCM_PR_DEBUG("%s(%s): %s\n", __func__, ch->id, dev->name);
+
 	duration =
 	    (done_stamp.tv_sec - ch->prof.send_stamp.tv_sec) * 1000000 +
 	    (done_stamp.tv_nsec - ch->prof.send_stamp.tv_nsec) / 1000;
@@ -258,8 +261,9 @@ static void chx_txdone(fsm_instance *fi, int event, void *arg)
 		ch->prof.tx_time = duration;
 
 	if (ch->irb->scsw.cmd.count != 0)
-		ctcm_pr_debug("%s: TX not complete, remaining %d bytes\n",
-			     dev->name, ch->irb->scsw.cmd.count);
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_DEBUG,
+			"%s(%s): TX not complete, remaining %d bytes",
+			     CTCM_FUNTAIL, dev->name, ch->irb->scsw.cmd.count);
 	fsm_deltimer(&ch->timer);
 	while ((skb = skb_dequeue(&ch->io_queue))) {
 		priv->stats.tx_packets++;
@@ -334,7 +338,8 @@ void ctcm_chx_txidle(fsm_instance *fi, int event, void *arg)
 	struct net_device *dev = ch->netdev;
 	struct ctcm_priv *priv = dev->priv;
 
-	CTCM_DBF_TEXT(TRACE, 6, __FUNCTION__);
+	CTCM_PR_DEBUG("%s(%s): %s\n", __func__, ch->id, dev->name);
+
 	fsm_deltimer(&ch->timer);
 	fsm_newstate(fi, CTC_STATE_TXIDLE);
 	fsm_event(priv->fsm, DEV_EVENT_TXUP, ch->netdev);
@@ -361,15 +366,17 @@ static void chx_rx(fsm_instance *fi, int event, void *arg)
 
 	fsm_deltimer(&ch->timer);
 	if (len < 8) {
-		ctcm_pr_debug("%s: got packet with length %d < 8\n",
-			     dev->name, len);
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_NOTICE,
+			"%s(%s): got packet with length %d < 8\n",
+					CTCM_FUNTAIL, dev->name, len);
 		priv->stats.rx_dropped++;
 		priv->stats.rx_length_errors++;
 						goto again;
 	}
 	if (len > ch->max_bufsize) {
-		ctcm_pr_debug("%s: got packet with length %d > %d\n",
-			     dev->name, len, ch->max_bufsize);
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_NOTICE,
+			"%s(%s): got packet with length %d > %d\n",
+				CTCM_FUNTAIL, dev->name, len, ch->max_bufsize);
 		priv->stats.rx_dropped++;
 		priv->stats.rx_length_errors++;
 						goto again;
@@ -388,8 +395,9 @@ static void chx_rx(fsm_instance *fi, int event, void *arg)
 		break;
 	}
 	if ((len < block_len) || (len > check_len)) {
-		ctcm_pr_debug("%s: got block length %d != rx length %d\n",
-			     dev->name, block_len, len);
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_NOTICE,
+			"%s(%s): got block length %d != rx length %d\n",
+				CTCM_FUNTAIL, dev->name, block_len, len);
 		if (do_debug)
 			ctcmpc_dump_skb(skb, 0);
 
@@ -425,17 +433,23 @@ static void chx_rx(fsm_instance *fi, int event, void *arg)
  */
 static void chx_firstio(fsm_instance *fi, int event, void *arg)
 {
-	struct channel *ch = arg;
 	int rc;
+	struct channel *ch = arg;
+	int fsmstate = fsm_getstate(fi);
 
-	CTCM_DBF_TEXT(TRACE, 6, __FUNCTION__);
+	CTCM_DBF_TEXT_(TRACE, CTC_DBF_NOTICE,
+		"%s(%s) : %02x",
+		CTCM_FUNTAIL, ch->id, fsmstate);
 
-	if (fsm_getstate(fi) == CTC_STATE_TXIDLE)
-		ctcm_pr_debug("%s: remote side issued READ?, init.\n", ch->id);
+	ch->sense_rc = 0;	/* reset unit check report control */
+	if (fsmstate == CTC_STATE_TXIDLE)
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_DEBUG,
+			"%s(%s): remote side issued READ?, init.\n",
+				CTCM_FUNTAIL, ch->id);
 	fsm_deltimer(&ch->timer);
 	if (ctcm_checkalloc_buffer(ch))
 		return;
-	if ((fsm_getstate(fi) == CTC_STATE_SETUPWAIT) &&
+	if ((fsmstate == CTC_STATE_SETUPWAIT) &&
 	    (ch->protocol == CTCM_PROTO_OS390)) {
 		/* OS/390 resp. z/OS */
 		if (CHANNEL_DIRECTION(ch->flags) == READ) {
@@ -451,7 +465,6 @@ static void chx_firstio(fsm_instance *fi, int event, void *arg)
 		}
 		return;
 	}
-
 	/*
 	 * Don't setup a timer for receiving the initial RX frame
 	 * if in compatibility mode, since VM TCP delays the initial
@@ -505,11 +518,10 @@ static void chx_rxidle(fsm_instance *fi, int event, void *arg)
 	__u16 buflen;
 	int rc;
 
-	CTCM_DBF_TEXT(TRACE, 6, __FUNCTION__);
 	fsm_deltimer(&ch->timer);
 	buflen = *((__u16 *)ch->trans_skb->data);
-	if (do_debug)
-		ctcm_pr_debug("%s: Initial RX count %d\n", dev->name, buflen);
+	CTCM_PR_DEBUG("%s: %s: Initial RX count = %d\n",
+			__func__, dev->name, buflen);
 
 	if (buflen >= CTCM_INITIAL_BLOCKLEN) {
 		if (ctcm_checkalloc_buffer(ch))
@@ -524,9 +536,9 @@ static void chx_rxidle(fsm_instance *fi, int event, void *arg)
 		} else
 			fsm_event(priv->fsm, DEV_EVENT_RXUP, dev);
 	} else {
-		if (do_debug)
-			ctcm_pr_debug("%s: Initial RX count %d not %d\n",
-				dev->name, buflen, CTCM_INITIAL_BLOCKLEN);
+		CTCM_PR_DEBUG("%s: %s: Initial RX count %d not %d\n",
+				__func__, dev->name,
+					buflen, CTCM_INITIAL_BLOCKLEN);
 		chx_firstio(fi, event, arg);
 	}
 }
@@ -548,14 +560,12 @@ static void ctcm_chx_setmode(fsm_instance *fi, int event, void *arg)
 	fsm_deltimer(&ch->timer);
 	if (IS_MPC(ch)) {
 		timeout = 1500;
-		if (do_debug)
-			ctcm_pr_debug("ctcm enter: %s(): cp=%i ch=0x%p id=%s\n",
-				__FUNCTION__, smp_processor_id(), ch, ch->id);
+		CTCM_PR_DEBUG("enter %s: cp=%i ch=0x%p id=%s\n",
+				__func__, smp_processor_id(), ch, ch->id);
 	}
 	fsm_addtimer(&ch->timer, timeout, CTC_EVENT_TIMER, ch);
 	fsm_newstate(fi, CTC_STATE_SETUPWAIT);
-	if (do_debug_ccw && IS_MPC(ch))
-		ctcmpc_dumpit((char *)&ch->ccw[6], sizeof(struct ccw1) * 2);
+	CTCM_CCW_DUMP((char *)&ch->ccw[6], sizeof(struct ccw1) * 2);
 
 	if (event == CTC_EVENT_TIMER)	/* only for timer not yet locked */
 		spin_lock_irqsave(get_ccwdev_lock(ch->cdev), saveflags);
@@ -583,24 +593,12 @@ static void ctcm_chx_setmode(fsm_instance *fi, int event, void *arg)
  */
 static void ctcm_chx_start(fsm_instance *fi, int event, void *arg)
 {
-	struct channel *ch = arg;
-	int rc;
-	struct net_device *dev;
+	struct channel *ch	= arg;
 	unsigned long saveflags;
+	int rc;
 
-	CTCM_DBF_TEXT(TRACE, 5, __FUNCTION__);
-	if (ch == NULL) {
-		ctcm_pr_warn("chx_start ch=NULL\n");
-		return;
-	}
-	if (ch->netdev == NULL) {
-		ctcm_pr_warn("chx_start dev=NULL, id=%s\n", ch->id);
-		return;
-	}
-	dev = ch->netdev;
-
-	if (do_debug)
-		ctcm_pr_debug("%s: %s channel start\n", dev->name,
+	CTCM_DBF_TEXT_(SETUP, CTC_DBF_INFO, "%s(%s): %s",
+			CTCM_FUNTAIL, ch->id,
 			(CHANNEL_DIRECTION(ch->flags) == READ) ? "RX" : "TX");
 
 	if (ch->trans_skb != NULL) {
@@ -618,11 +616,12 @@ static void ctcm_chx_start(fsm_instance *fi, int event, void *arg)
 		ch->ccw[1].count = 0;
 	}
 	if (ctcm_checkalloc_buffer(ch)) {
-		ctcm_pr_notice("%s: %s trans_skb allocation delayed "
-				"until first transfer\n", dev->name,
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_DEBUG,
+			"%s(%s): %s trans_skb alloc delayed "
+			"until first transfer",
+			CTCM_FUNTAIL, ch->id,
 			(CHANNEL_DIRECTION(ch->flags) == READ) ? "RX" : "TX");
 	}
-
 	ch->ccw[0].cmd_code = CCW_CMD_PREPARE;
 	ch->ccw[0].flags = CCW_FLAG_SLI | CCW_FLAG_CC;
 	ch->ccw[0].count = 0;
@@ -661,7 +660,6 @@ static void ctcm_chx_haltio(fsm_instance *fi, int event, void *arg)
 	int rc;
 	int oldstate;
 
-	CTCM_DBF_TEXT(TRACE, 2, __FUNCTION__);
 	fsm_deltimer(&ch->timer);
 	if (IS_MPC(ch))
 		fsm_deltimer(&ch->sweep_timer);
@@ -684,7 +682,7 @@ static void ctcm_chx_haltio(fsm_instance *fi, int event, void *arg)
 		fsm_deltimer(&ch->timer);
 		if (event != CTC_EVENT_STOP) {
 			fsm_newstate(fi, oldstate);
-			ctcm_ccw_check_rc(ch, rc, (char *)__FUNCTION__);
+			ctcm_ccw_check_rc(ch, rc, (char *)__func__);
 		}
 	}
 }
@@ -703,7 +701,9 @@ static void ctcm_chx_cleanup(fsm_instance *fi, int state,
 	struct net_device *dev = ch->netdev;
 	struct ctcm_priv *priv = dev->priv;
 
-	CTCM_DBF_TEXT(TRACE, 3, __FUNCTION__);
+	CTCM_DBF_TEXT_(SETUP, CTC_DBF_NOTICE,
+			"%s(%s): %s[%d]\n",
+			CTCM_FUNTAIL, dev->name, ch->id, state);
 
 	fsm_deltimer(&ch->timer);
 	if (IS_MPC(ch))
@@ -743,7 +743,6 @@ static void ctcm_chx_cleanup(fsm_instance *fi, int state,
  */
 static void ctcm_chx_stopped(fsm_instance *fi, int event, void *arg)
 {
-	CTCM_DBF_TEXT(TRACE, 3, __FUNCTION__);
 	ctcm_chx_cleanup(fi, CTC_STATE_STOPPED, arg);
 }
 
@@ -771,7 +770,6 @@ static void ctcm_chx_stop(fsm_instance *fi, int event, void *arg)
  */
 static void ctcm_chx_fail(fsm_instance *fi, int event, void *arg)
 {
-	CTCM_DBF_TEXT(TRACE, 3, __FUNCTION__);
 	ctcm_chx_cleanup(fi, CTC_STATE_NOTOP, arg);
 }
 
@@ -809,8 +807,8 @@ static void ctcm_chx_setuperr(fsm_instance *fi, int event, void *arg)
 	}
 
 	CTCM_DBF_TEXT_(ERROR, CTC_DBF_CRIT,
-		"%s : %s error during %s channel setup state=%s\n",
-		dev->name, ctc_ch_event_names[event],
+		"%s(%s) : %s error during %s channel setup state=%s\n",
+		CTCM_FUNTAIL, dev->name, ctc_ch_event_names[event],
 		(CHANNEL_DIRECTION(ch->flags) == READ) ? "RX" : "TX",
 		fsm_getstate_str(fi));
 
@@ -838,10 +836,12 @@ static void ctcm_chx_restart(fsm_instance *fi, int event, void *arg)
 	int oldstate;
 	int rc;
 
-	CTCM_DBF_TEXT(TRACE, CTC_DBF_NOTICE, __FUNCTION__);
+	CTCM_DBF_TEXT_(TRACE, CTC_DBF_NOTICE,
+		"%s: %s[%d] of %s\n",
+			CTCM_FUNTAIL, ch->id, event, dev->name);
+
 	fsm_deltimer(&ch->timer);
-	ctcm_pr_debug("%s: %s channel restart\n", dev->name,
-		     (CHANNEL_DIRECTION(ch->flags) == READ) ? "RX" : "TX");
+
 	fsm_addtimer(&ch->timer, CTCM_TIME_5_SEC, CTC_EVENT_TIMER, ch);
 	oldstate = fsm_getstate(fi);
 	fsm_newstate(fi, CTC_STATE_STARTWAIT);
@@ -876,13 +876,10 @@ static void ctcm_chx_rxiniterr(fsm_instance *fi, int event, void *arg)
 	struct net_device *dev = ch->netdev;
 	struct ctcm_priv *priv = dev->priv;
 
-	CTCM_DBF_TEXT(SETUP, 3, __FUNCTION__);
 	if (event == CTC_EVENT_TIMER) {
 		if (!IS_MPCDEV(dev))
 			/* TODO : check if MPC deletes timer somewhere */
 			fsm_deltimer(&ch->timer);
-		ctcm_pr_debug("%s: Timeout during RX init handshake\n",
-				dev->name);
 		if (ch->retry++ < 3)
 			ctcm_chx_restart(fi, event, arg);
 		else {
@@ -907,9 +904,10 @@ static void ctcm_chx_rxinitfail(fsm_instance *fi, int event, void *arg)
 	struct net_device *dev = ch->netdev;
 	struct ctcm_priv *priv = dev->priv;
 
-	CTCM_DBF_TEXT(SETUP, 3, __FUNCTION__);
+	CTCM_DBF_TEXT_(ERROR, CTC_DBF_ERROR,
+			"%s(%s): RX %s busy, init. fail",
+				CTCM_FUNTAIL, dev->name, ch->id);
 	fsm_newstate(fi, CTC_STATE_RXERR);
-	ctcm_pr_warn("%s: RX busy. Initialization failed\n", dev->name);
 	fsm_event(priv->fsm, DEV_EVENT_RXDOWN, dev);
 }
 
@@ -927,11 +925,10 @@ static void ctcm_chx_rxdisc(fsm_instance *fi, int event, void *arg)
 	struct net_device *dev = ch->netdev;
 	struct ctcm_priv *priv = dev->priv;
 
-	CTCM_DBF_DEV_NAME(TRACE, dev, "Got remote disconnect, re-initializing");
+	CTCM_DBF_TEXT_(TRACE, CTC_DBF_NOTICE,
+			"%s: %s: remote disconnect - re-init ...",
+				CTCM_FUNTAIL, dev->name);
 	fsm_deltimer(&ch->timer);
-	if (do_debug)
-		ctcm_pr_debug("%s: Got remote disconnect, "
-				"re-initializing ...\n", dev->name);
 	/*
 	 * Notify device statemachine
 	 */
@@ -961,8 +958,6 @@ static void ctcm_chx_txiniterr(fsm_instance *fi, int event, void *arg)
 
 	if (event == CTC_EVENT_TIMER) {
 		fsm_deltimer(&ch->timer);
-		CTCM_DBF_DEV_NAME(ERROR, dev,
-				"Timeout during TX init handshake");
 		if (ch->retry++ < 3)
 			ctcm_chx_restart(fi, event, arg);
 		else {
@@ -971,9 +966,8 @@ static void ctcm_chx_txiniterr(fsm_instance *fi, int event, void *arg)
 		}
 	} else {
 		CTCM_DBF_TEXT_(ERROR, CTC_DBF_ERROR,
-			"%s : %s error during channel setup state=%s",
-			dev->name, ctc_ch_event_names[event],
-			fsm_getstate_str(fi));
+			"%s(%s): %s in %s", CTCM_FUNTAIL, ch->id,
+			ctc_ch_event_names[event], fsm_getstate_str(fi));
 
 		ctcm_pr_warn("%s: Error during TX init handshake\n", dev->name);
 	}
@@ -993,15 +987,15 @@ static void ctcm_chx_txretry(fsm_instance *fi, int event, void *arg)
 	struct ctcm_priv *priv = dev->priv;
 	struct sk_buff *skb;
 
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc enter: %s(): cp=%i ch=0x%p id=%s\n",
-			__FUNCTION__, smp_processor_id(), ch, ch->id);
+	CTCM_PR_DEBUG("Enter: %s: cp=%i ch=0x%p id=%s\n",
+			__func__, smp_processor_id(), ch, ch->id);
 
 	fsm_deltimer(&ch->timer);
 	if (ch->retry++ > 3) {
 		struct mpc_group *gptr = priv->mpcg;
-		ctcm_pr_debug("%s: TX retry failed, restarting channel\n",
-			     dev->name);
+		CTCM_DBF_TEXT_(TRACE, CTC_DBF_INFO,
+				"%s: %s: retries exceeded",
+					CTCM_FUNTAIL, ch->id);
 		fsm_event(priv->fsm, DEV_EVENT_TXDOWN, dev);
 		/* call restart if not MPC or if MPC and mpcg fsm is ready.
 			use gptr as mpc indicator */
@@ -1010,7 +1004,9 @@ static void ctcm_chx_txretry(fsm_instance *fi, int event, void *arg)
 				goto done;
 	}
 
-	ctcm_pr_debug("%s: TX retry %d\n", dev->name, ch->retry);
+	CTCM_DBF_TEXT_(TRACE, CTC_DBF_DEBUG,
+			"%s : %s: retry %d",
+				CTCM_FUNTAIL, ch->id, ch->retry);
 	skb = skb_peek(&ch->io_queue);
 	if (skb) {
 		int rc = 0;
@@ -1018,8 +1014,9 @@ static void ctcm_chx_txretry(fsm_instance *fi, int event, void *arg)
 		clear_normalized_cda(&ch->ccw[4]);
 		ch->ccw[4].count = skb->len;
 		if (set_normalized_cda(&ch->ccw[4], skb->data)) {
-			ctcm_pr_debug("%s: IDAL alloc failed, chan restart\n",
-						dev->name);
+			CTCM_DBF_TEXT_(TRACE, CTC_DBF_INFO,
+				"%s: %s: IDAL alloc failed",
+						CTCM_FUNTAIL, ch->id);
 			fsm_event(priv->fsm, DEV_EVENT_TXDOWN, dev);
 			ctcm_chx_restart(fi, event, arg);
 				goto done;
@@ -1061,22 +1058,21 @@ static void ctcm_chx_iofatal(fsm_instance *fi, int event, void *arg)
 	struct channel *ch = arg;
 	struct net_device *dev = ch->netdev;
 	struct ctcm_priv *priv = dev->priv;
+	int rd = CHANNEL_DIRECTION(ch->flags);
 
-	CTCM_DBF_TEXT(TRACE, 3, __FUNCTION__);
 	fsm_deltimer(&ch->timer);
-	ctcm_pr_warn("%s %s : unrecoverable channel error\n",
-			CTC_DRIVER_NAME, dev->name);
+	CTCM_DBF_TEXT_(ERROR, CTC_DBF_ERROR,
+		"%s: %s: %s unrecoverable channel error",
+			CTCM_FUNTAIL, ch->id, rd == READ ? "RX" : "TX");
+
 	if (IS_MPC(ch)) {
 		priv->stats.tx_dropped++;
 		priv->stats.tx_errors++;
 	}
-
-	if (CHANNEL_DIRECTION(ch->flags) == READ) {
-		ctcm_pr_debug("%s: RX I/O error\n", dev->name);
+	if (rd == READ) {
 		fsm_newstate(fi, CTC_STATE_RXERR);
 		fsm_event(priv->fsm, DEV_EVENT_RXDOWN, dev);
 	} else {
-		ctcm_pr_debug("%s: TX I/O error\n", dev->name);
 		fsm_newstate(fi, CTC_STATE_TXERR);
 		fsm_event(priv->fsm, DEV_EVENT_TXDOWN, dev);
 	}
@@ -1216,27 +1212,27 @@ static void ctcmpc_chx_txdone(fsm_instance *fi, int event, void *arg)
 	struct sk_buff		*skb;
 	int		first = 1;
 	int		i;
-	struct timespec done_stamp;
 	__u32		data_space;
 	unsigned long	duration;
 	struct sk_buff	*peekskb;
 	int		rc;
 	struct th_header *header;
 	struct pdu	*p_header;
+	struct timespec done_stamp = current_kernel_time(); /* xtime */
 
-	if (do_debug)
-		ctcm_pr_debug("%s cp:%i enter:  %s()\n",
-			dev->name, smp_processor_id(), __FUNCTION__);
+	CTCM_PR_DEBUG("Enter %s: %s cp:%i\n",
+			__func__, dev->name, smp_processor_id());
 
-	done_stamp = current_kernel_time(); /* xtime */
-	duration = (done_stamp.tv_sec - ch->prof.send_stamp.tv_sec) * 1000000
-		+ (done_stamp.tv_nsec - ch->prof.send_stamp.tv_nsec) / 1000;
+	duration =
+		(done_stamp.tv_sec - ch->prof.send_stamp.tv_sec) * 1000000 +
+		(done_stamp.tv_nsec - ch->prof.send_stamp.tv_nsec) / 1000;
 	if (duration > ch->prof.tx_time)
 		ch->prof.tx_time = duration;
 
 	if (ch->irb->scsw.cmd.count != 0)
-		ctcm_pr_debug("%s: TX not complete, remaining %d bytes\n",
-				dev->name, ch->irb->scsw.cmd.count);
+		CTCM_DBF_TEXT_(MPC_TRACE, CTC_DBF_DEBUG,
+			"%s(%s): TX not complete, remaining %d bytes",
+			     CTCM_FUNTAIL, dev->name, ch->irb->scsw.cmd.count);
 	fsm_deltimer(&ch->timer);
 	while ((skb = skb_dequeue(&ch->io_queue))) {
 		priv->stats.tx_packets++;
@@ -1250,7 +1246,6 @@ static void ctcmpc_chx_txdone(fsm_instance *fi, int event, void *arg)
 	}
 	spin_lock(&ch->collect_lock);
 	clear_normalized_cda(&ch->ccw[4]);
-
 	if ((ch->collect_len <= 0) || (grp->in_sweep != 0)) {
 		spin_unlock(&ch->collect_lock);
 		fsm_newstate(fi, CTC_STATE_TXIDLE);
@@ -1269,17 +1264,13 @@ static void ctcmpc_chx_txdone(fsm_instance *fi, int event, void *arg)
 	if (ch->prof.maxcqueue < skb_queue_len(&ch->collect_queue))
 		ch->prof.maxcqueue = skb_queue_len(&ch->collect_queue);
 	i = 0;
-
-	if (do_debug_data)
-		ctcm_pr_debug("ctcmpc: %s() building "
-			       "trans_skb from collect_q \n", __FUNCTION__);
-
+	p_header = NULL;
 	data_space = grp->group_max_buflen - TH_HEADER_LENGTH;
 
-	if (do_debug_data)
-		ctcm_pr_debug("ctcmpc: %s() building trans_skb from collect_q"
-		       " data_space:%04x\n", __FUNCTION__, data_space);
-	p_header = NULL;
+	CTCM_PR_DBGDATA("%s: building trans_skb from collect_q"
+		       " data_space:%04x\n",
+		       __func__, data_space);
+
 	while ((skb = skb_dequeue(&ch->collect_queue))) {
 		memcpy(skb_put(ch->trans_skb, skb->len), skb->data, skb->len);
 		p_header = (struct pdu *)
@@ -1290,15 +1281,12 @@ static void ctcmpc_chx_txdone(fsm_instance *fi, int event, void *arg)
 		else
 			p_header->pdu_flag |= 0x20;
 
-		if (do_debug_data) {
-			ctcm_pr_debug("ctcmpc: %s()trans_skb len:%04x \n",
-				       __FUNCTION__, ch->trans_skb->len);
-			ctcm_pr_debug("ctcmpc: %s() pdu header and data"
-				       " for up to 32 bytes sent to vtam\n",
-				       __FUNCTION__);
-			ctcmpc_dumpit((char *)p_header,
-						min_t(int, skb->len, 32));
-		}
+		CTCM_PR_DBGDATA("%s: trans_skb len:%04x \n",
+				__func__, ch->trans_skb->len);
+		CTCM_PR_DBGDATA("%s: pdu header and data for up"
+				" to 32 bytes sent to vtam\n", __func__);
+		CTCM_D3_DUMP((char *)p_header, min_t(int, skb->len, 32));
+
 		ch->collect_len -= skb->len;
 		data_space -= skb->len;
 		priv->stats.tx_packets++;
@@ -1314,46 +1302,38 @@ static void ctcmpc_chx_txdone(fsm_instance *fi, int event, void *arg)
 	if (p_header)
 		p_header->pdu_flag |= PDU_LAST;	/*Say it's the last one*/
 	header = kzalloc(TH_HEADER_LENGTH, gfp_type());
-
 	if (!header) {
-		printk(KERN_WARNING "ctcmpc: OUT OF MEMORY IN %s()"
-		       ": Data Lost \n", __FUNCTION__);
 		spin_unlock(&ch->collect_lock);
 		fsm_event(priv->mpcg->fsm, MPCG_EVENT_INOP, dev);
-		goto done;
+				goto done;
 	}
-
 	header->th_ch_flag = TH_HAS_PDU;  /* Normal data */
 	ch->th_seq_num++;
 	header->th_seq_num = ch->th_seq_num;
 
-	if (do_debug_data)
-		ctcm_pr_debug("%s: ToVTAM_th_seq= %08x\n" ,
-					__FUNCTION__, ch->th_seq_num);
+	CTCM_PR_DBGDATA("%s: ToVTAM_th_seq= %08x\n" ,
+					__func__, ch->th_seq_num);
 
 	memcpy(skb_push(ch->trans_skb, TH_HEADER_LENGTH), header,
 		TH_HEADER_LENGTH);	/* put the TH on the packet */
 
 	kfree(header);
 
-	if (do_debug_data) {
-		ctcm_pr_debug("ctcmpc: %s()trans_skb len:%04x \n",
-		       __FUNCTION__, ch->trans_skb->len);
-
-		ctcm_pr_debug("ctcmpc: %s() up-to-50 bytes of trans_skb "
-			"data to vtam from collect_q\n", __FUNCTION__);
-		ctcmpc_dumpit((char *)ch->trans_skb->data,
+	CTCM_PR_DBGDATA("%s: trans_skb len:%04x \n",
+		       __func__, ch->trans_skb->len);
+	CTCM_PR_DBGDATA("%s: up-to-50 bytes of trans_skb "
+			"data to vtam from collect_q\n", __func__);
+	CTCM_D3_DUMP((char *)ch->trans_skb->data,
 				min_t(int, ch->trans_skb->len, 50));
-	}
 
 	spin_unlock(&ch->collect_lock);
 	clear_normalized_cda(&ch->ccw[1]);
 	if (set_normalized_cda(&ch->ccw[1], ch->trans_skb->data)) {
 		dev_kfree_skb_any(ch->trans_skb);
 		ch->trans_skb = NULL;
-		printk(KERN_WARNING
-		       "ctcmpc: %s()CCW failure - data lost\n",
-		       __FUNCTION__);
+		CTCM_DBF_TEXT_(MPC_TRACE, CTC_DBF_ERROR,
+			"%s: %s: IDAL alloc failed",
+				CTCM_FUNTAIL, ch->id);
 		fsm_event(priv->mpcg->fsm, MPCG_EVENT_INOP, dev);
 		return;
 	}
@@ -1373,7 +1353,6 @@ static void ctcmpc_chx_txdone(fsm_instance *fi, int event, void *arg)
 	}
 done:
 	ctcm_clear_busy(dev);
-	ctcm_pr_debug("ctcmpc exit: %s  %s()\n", dev->name, __FUNCTION__);
 	return;
 }
 
@@ -1393,26 +1372,25 @@ static void ctcmpc_chx_rx(fsm_instance *fi, int event, void *arg)
 	struct mpc_group	*grp = priv->mpcg;
 	struct sk_buff		*skb = ch->trans_skb;
 	struct sk_buff		*new_skb;
-	unsigned long	saveflags = 0;	/* avoids compiler warning */
+	unsigned long		saveflags = 0;	/* avoids compiler warning */
 	int len	= ch->max_bufsize - ch->irb->scsw.cmd.count;
 
-	if (do_debug_data) {
-		CTCM_DBF_TEXT_(TRACE, CTC_DBF_DEBUG, "mpc_ch_rx %s cp:%i %s\n",
-				dev->name, smp_processor_id(), ch->id);
-		CTCM_DBF_TEXT_(TRACE, CTC_DBF_DEBUG, "mpc_ch_rx: maxbuf: %04x "
-				"len: %04x\n", ch->max_bufsize, len);
-	}
+	CTCM_PR_DEBUG("%s: %s: cp:%i %s maxbuf : %04x, len: %04x\n",
+			CTCM_FUNTAIL, dev->name, smp_processor_id(),
+				ch->id, ch->max_bufsize, len);
 	fsm_deltimer(&ch->timer);
 
 	if (skb == NULL) {
-		ctcm_pr_debug("ctcmpc exit:  %s() TRANS_SKB = NULL \n",
-			       __FUNCTION__);
-					goto again;
+		CTCM_DBF_TEXT_(MPC_ERROR, CTC_DBF_ERROR,
+			"%s(%s): TRANS_SKB = NULL",
+				CTCM_FUNTAIL, dev->name);
+			goto again;
 	}
 
 	if (len < TH_HEADER_LENGTH) {
-		ctcm_pr_info("%s: got packet with invalid length %d\n",
-				dev->name, len);
+		CTCM_DBF_TEXT_(MPC_ERROR, CTC_DBF_ERROR,
+				"%s(%s): packet length %d to short",
+					CTCM_FUNTAIL, dev->name, len);
 		priv->stats.rx_dropped++;
 		priv->stats.rx_length_errors++;
 	} else {
@@ -1422,11 +1400,9 @@ static void ctcmpc_chx_rx(fsm_instance *fi, int event, void *arg)
 		new_skb = __dev_alloc_skb(ch->max_bufsize, GFP_ATOMIC);
 
 		if (new_skb == NULL) {
-			printk(KERN_INFO "ctcmpc:%s() NEW_SKB = NULL\n",
-			       __FUNCTION__);
-			printk(KERN_WARNING "ctcmpc: %s() MEMORY ALLOC FAILED"
-			       " - DATA LOST - MPC FAILED\n",
-			       __FUNCTION__);
+			CTCM_DBF_TEXT_(MPC_ERROR, CTC_DBF_ERROR,
+				"%s(%d): skb allocation failed",
+						CTCM_FUNTAIL, dev->name);
 			fsm_event(priv->mpcg->fsm, MPCG_EVENT_INOP, dev);
 					goto again;
 		}
@@ -1479,9 +1455,8 @@ again:
 		break;
 	}
 
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc exit : %s %s(): ch=0x%p id=%s\n",
-				dev->name, __FUNCTION__, ch, ch->id);
+	CTCM_PR_DEBUG("Exit %s: %s, ch=0x%p, id=%s\n",
+			__func__, dev->name, ch, ch->id);
 
 }
 
@@ -1497,15 +1472,16 @@ static void ctcmpc_chx_firstio(fsm_instance *fi, int event, void *arg)
 	struct channel		*ch = arg;
 	struct net_device	*dev = ch->netdev;
 	struct ctcm_priv	*priv = dev->priv;
+	struct mpc_group	*gptr = priv->mpcg;
+
+	CTCM_PR_DEBUG("Enter %s: id=%s, ch=0x%p\n",
+				__func__, ch->id, ch);
+
+	CTCM_DBF_TEXT_(MPC_TRACE, CTC_DBF_INFO,
+			"%s: %s: chstate:%i, grpstate:%i, prot:%i\n",
+			CTCM_FUNTAIL, ch->id, fsm_getstate(fi),
+			fsm_getstate(gptr->fsm), ch->protocol);
 
-	if (do_debug) {
-		struct mpc_group *gptr = priv->mpcg;
-		ctcm_pr_debug("ctcmpc enter: %s(): ch=0x%p id=%s\n",
-				__FUNCTION__, ch, ch->id);
-		ctcm_pr_debug("%s() %s chstate:%i grpstate:%i chprotocol:%i\n",
-				__FUNCTION__, ch->id, fsm_getstate(fi),
-				fsm_getstate(gptr->fsm), ch->protocol);
-	}
 	if (fsm_getstate(fi) == CTC_STATE_TXIDLE)
 		MPC_DBF_DEV_NAME(TRACE, dev, "remote side issued READ? ");
 
@@ -1531,9 +1507,8 @@ static void ctcmpc_chx_firstio(fsm_instance *fi, int event, void *arg)
 		     ? CTC_STATE_RXINIT : CTC_STATE_TXINIT);
 
 done:
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc exit : %s(): ch=0x%p id=%s\n",
-			__FUNCTION__, ch, ch->id);
+	CTCM_PR_DEBUG("Exit %s: id=%s, ch=0x%p\n",
+				__func__, ch->id, ch);
 	return;
 }
 
@@ -1556,12 +1531,9 @@ void ctcmpc_chx_rxidle(fsm_instance *fi, int event, void *arg)
 	unsigned long saveflags = 0;	/* avoids compiler warning */
 
 	fsm_deltimer(&ch->timer);
-	ctcm_pr_debug("%s cp:%i enter:  %s()\n",
-		       dev->name, smp_processor_id(), __FUNCTION__);
-	if (do_debug)
-		ctcm_pr_debug("%s() %s chstate:%i grpstate:%i\n",
-			__FUNCTION__, ch->id,
-			fsm_getstate(fi), fsm_getstate(grp->fsm));
+	CTCM_PR_DEBUG("%s: %s: %s: cp:%i, chstate:%i grpstate:%i\n",
+			__func__, ch->id, dev->name, smp_processor_id(),
+				fsm_getstate(fi), fsm_getstate(grp->fsm));
 
 	fsm_newstate(fi, CTC_STATE_RXIDLE);
 	/* XID processing complete */
@@ -1575,9 +1547,7 @@ void ctcmpc_chx_rxidle(fsm_instance *fi, int event, void *arg)
 		skb_reset_tail_pointer(ch->trans_skb);
 		ch->trans_skb->len = 0;
 		ch->ccw[1].count = ch->max_bufsize;
-		if (do_debug_ccw)
-			ctcmpc_dumpit((char *)&ch->ccw[0],
-						sizeof(struct ccw1) * 3);
+		CTCM_CCW_DUMP((char *)&ch->ccw[0], sizeof(struct ccw1) * 3);
 		if (event == CTC_EVENT_START)
 			/* see remark about conditional locking */
 			spin_lock_irqsave(get_ccwdev_lock(ch->cdev), saveflags);
@@ -1598,9 +1568,6 @@ void ctcmpc_chx_rxidle(fsm_instance *fi, int event, void *arg)
 
 	fsm_event(priv->fsm, DEV_EVENT_RXUP, dev);
 done:
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc exit: %s  %s()\n",
-					dev->name, __FUNCTION__);
 	return;
 }
 
@@ -1616,13 +1583,9 @@ static void ctcmpc_chx_attn(fsm_instance *fsm, int event, void *arg)
 	struct ctcm_priv  *priv   = dev->priv;
 	struct mpc_group  *grp = priv->mpcg;
 
-	if (do_debug) {
-		ctcm_pr_debug("ctcmpc enter: %s(): cp=%i ch=0x%p id=%s"
-				"GrpState:%s ChState:%s\n",
-				__FUNCTION__, smp_processor_id(), ch, ch->id,
-		fsm_getstate_str(grp->fsm),
-		fsm_getstate_str(ch->fsm));
-	}
+	CTCM_PR_DEBUG("%s(%s): %s(ch=0x%p), cp=%i, ChStat:%s, GrpStat:%s\n",
+		__func__, dev->name, ch->id, ch, smp_processor_id(),
+			fsm_getstate_str(ch->fsm), fsm_getstate_str(grp->fsm));
 
 	switch (fsm_getstate(grp->fsm)) {
 	case MPCG_STATE_XID2INITW:
@@ -1664,11 +1627,7 @@ static void ctcmpc_chx_attn(fsm_instance *fsm, int event, void *arg)
 		break;
 	}
 
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc exit : %s(): cp=%i ch=0x%p id=%s\n",
-			__FUNCTION__, smp_processor_id(), ch, ch->id);
 	return;
-
 }
 
 /*
@@ -1683,11 +1642,9 @@ static void ctcmpc_chx_attnbusy(fsm_instance *fsm, int event, void *arg)
 	struct ctcm_priv  *priv   = dev->priv;
 	struct mpc_group  *grp    = priv->mpcg;
 
-	ctcm_pr_debug("ctcmpc enter: %s  %s() %s  \nGrpState:%s ChState:%s\n",
-		       dev->name,
-		       __FUNCTION__, ch->id,
-		       fsm_getstate_str(grp->fsm),
-		       fsm_getstate_str(ch->fsm));
+	CTCM_PR_DEBUG("%s(%s): %s\n  ChState:%s GrpState:%s\n",
+			__func__, dev->name, ch->id,
+			fsm_getstate_str(ch->fsm), fsm_getstate_str(grp->fsm));
 
 	fsm_deltimer(&ch->timer);
 
@@ -1750,16 +1707,12 @@ static void ctcmpc_chx_attnbusy(fsm_instance *fsm, int event, void *arg)
 	if (ch->in_mpcgroup)
 		fsm_event(grp->fsm, MPCG_EVENT_XID0DO, ch);
 	else
-		printk(KERN_WARNING "ctcmpc: %s() Not all channels have"
-			" been added to group\n", __FUNCTION__);
+		CTCM_DBF_TEXT_(MPC_ERROR, CTC_DBF_ERROR,
+			"%s(%s): channel %s not added to group",
+				CTCM_FUNTAIL, dev->name, ch->id);
 
 done:
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc exit : %s()%s ch=0x%p id=%s\n",
-				__FUNCTION__, dev->name, ch, ch->id);
-
 	return;
-
 }
 
 /*
@@ -1774,13 +1727,7 @@ static void ctcmpc_chx_resend(fsm_instance *fsm, int event, void *arg)
 	struct ctcm_priv   *priv   = dev->priv;
 	struct mpc_group   *grp    = priv->mpcg;
 
-	ctcm_pr_debug("ctcmpc enter: %s  %s() %s  \nGrpState:%s ChState:%s\n",
-		       dev->name, __FUNCTION__, ch->id,
-		       fsm_getstate_str(grp->fsm),
-		       fsm_getstate_str(ch->fsm));
-
 	fsm_event(grp->fsm, MPCG_EVENT_XID0DO, ch);
-
 	return;
 }
 
@@ -1802,19 +1749,16 @@ static void ctcmpc_chx_send_sweep(fsm_instance *fsm, int event, void *arg)
 	int rc = 0;
 	unsigned long saveflags = 0;
 
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc enter: %s(): cp=%i ch=0x%p id=%s\n",
-			__FUNCTION__, smp_processor_id(), ach, ach->id);
+	CTCM_PR_DEBUG("ctcmpc enter: %s(): cp=%i ch=0x%p id=%s\n",
+			__func__, smp_processor_id(), ach, ach->id);
 
 	if (grp->in_sweep == 0)
 				goto done;
 
-	if (do_debug_data) {
-		ctcm_pr_debug("ctcmpc: %s() 1: ToVTAM_th_seq= %08x\n" ,
-			       __FUNCTION__, wch->th_seq_num);
-		ctcm_pr_debug("ctcmpc: %s() 1: FromVTAM_th_seq= %08x\n" ,
-				__FUNCTION__, rch->th_seq_num);
-	}
+	CTCM_PR_DBGDATA("%s: 1: ToVTAM_th_seq= %08x\n" ,
+				__func__, wch->th_seq_num);
+	CTCM_PR_DBGDATA("%s: 1: FromVTAM_th_seq= %08x\n" ,
+				__func__, rch->th_seq_num);
 
 	if (fsm_getstate(wch->fsm) != CTC_STATE_TXIDLE) {
 		/* give the previous IO time to complete */
@@ -1853,11 +1797,9 @@ static void ctcmpc_chx_send_sweep(fsm_instance *fsm, int event, void *arg)
 
 	header->sw.th_last_seq = wch->th_seq_num;
 
-	if (do_debug_ccw)
-		ctcmpc_dumpit((char *)&wch->ccw[3], sizeof(struct ccw1) * 3);
-
-	ctcm_pr_debug("ctcmpc: %s() sweep packet\n", __FUNCTION__);
-	ctcmpc_dumpit((char *)header, TH_SWEEP_LENGTH);
+	CTCM_CCW_DUMP((char *)&wch->ccw[3], sizeof(struct ccw1) * 3);
+	CTCM_PR_DBGDATA("%s: sweep packet\n", __func__);
+	CTCM_D3_DUMP((char *)header, TH_SWEEP_LENGTH);
 
 	fsm_addtimer(&wch->timer, CTCM_TIME_5_SEC, CTC_EVENT_TIMER, wch);
 	fsm_newstate(wch->fsm, CTC_STATE_TX);
@@ -1876,19 +1818,13 @@ static void ctcmpc_chx_send_sweep(fsm_instance *fsm, int event, void *arg)
 		ctcm_clear_busy_do(dev);
 	}
 
-	if (do_debug_data) {
-		ctcm_pr_debug("ctcmpc: %s()2: ToVTAM_th_seq= %08x\n" ,
-			       __FUNCTION__, wch->th_seq_num);
-		ctcm_pr_debug("ctcmpc: %s()2: FromVTAM_th_seq= %08x\n" ,
-			       __FUNCTION__, rch->th_seq_num);
-	}
+	CTCM_PR_DBGDATA("%s: To-/From-VTAM_th_seq = %08x/%08x\n" ,
+			__func__, wch->th_seq_num, rch->th_seq_num);
 
 	if (rc != 0)
 		ctcm_ccw_check_rc(wch, rc, "send sweep");
 
 done:
-	if (do_debug)
-		ctcm_pr_debug("ctcmpc exit:  %s() %s\n", __FUNCTION__, ach->id);
 	return;
 }
 
@@ -2149,9 +2085,8 @@ static void dev_action_stop(fsm_instance *fi, int event, void *arg)
 		struct channel *ch = priv->channel[direction];
 		fsm_event(ch->fsm, CTC_EVENT_STOP, ch);
 		ch->th_seq_num = 0x00;
-	if (do_debug)
-		ctcm_pr_debug("ctcm: %s() CH_th_seq= %08x\n",
-				__FUNCTION__, ch->th_seq_num);
+		CTCM_PR_DEBUG("%s: CH_th_seq= %08x\n",
+				__func__, ch->th_seq_num);
 	}
 	if (IS_MPC(priv))
 		fsm_newstate(priv->mpcg->fsm, MPCG_STATE_RESET);
@@ -2199,8 +2134,11 @@ static void dev_action_chup(fsm_instance *fi, int event, void *arg)
 {
 	struct net_device *dev = arg;
 	struct ctcm_priv *priv = dev->priv;
+	int dev_stat = fsm_getstate(fi);
 
-	CTCMY_DBF_DEV_NAME(SETUP, dev, "");
+	CTCM_DBF_TEXT_(SETUP, CTC_DBF_NOTICE,
+			"%s(%s): priv = %p [%d,%d]\n ",	CTCM_FUNTAIL,
+				dev->name, dev->priv, dev_stat, event);
 
 	switch (fsm_getstate(fi)) {
 	case DEV_STATE_STARTWAIT_RXTX: