net: sctp: rework debugging framework to use pr_debug and friends

We should get rid of all own SCTP debug printk macros and use the ones
that the kernel offers anyway instead. This makes the code more readable
and conform to the kernel code, and offers all the features of dynamic
debbuging that pr_debug() et al has, such as only turning on/off portions
of debug messages at runtime through debugfs. The runtime cost of having
CONFIG_DYNAMIC_DEBUG enabled, but none of the debug statements printing,
is negligible [1]. If kernel debugging is completly turned off, then these
statements will also compile into "empty" functions.

While we're at it, we also need to change the Kconfig option as it /now/
only refers to the ifdef'ed code portions in outqueue.c that enable further
debugging/tracing of SCTP transaction fields. Also, since SCTP_ASSERT code
was enabled with this Kconfig option and has now been removed, we
transform those code parts into WARNs resp. where appropriate BUG_ONs so
that those bugs can be more easily detected as probably not many people
have SCTP debugging permanently turned on.

To turn on all SCTP debugging, the following steps are needed:

 # mount -t debugfs none /sys/kernel/debug
 # echo -n 'module sctp +p' > /sys/kernel/debug/dynamic_debug/control

This can be done more fine-grained on a per file, per line basis and others
as described in [2].

 [1] https://www.kernel.org/doc/ols/2009/ols2009-pages-39-46.pdf
 [2] Documentation/dynamic-debug-howto.txt

Signed-off-by: Daniel Borkmann <dborkman@redhat.com>
Signed-off-by: David S. Miller <davem@davemloft.net>

1 files changed, 70 insertions, 90 deletions

diff --git a/net/sctp/outqueue.c b/net/sctp/outqueue.c
index be35e2d..511b3b3 100644
--- a/net/sctp/outqueue.c
+++ b/net/sctp/outqueue.c
@@ -299,10 +299,10 @@ int sctp_outq_tail(struct sctp_outq *q, struct sctp_chunk *chunk)
 	struct net *net = sock_net(q->asoc->base.sk);
 	int error = 0;
 
-	SCTP_DEBUG_PRINTK("sctp_outq_tail(%p, %p[%s])\n",
-			  q, chunk, chunk && chunk->chunk_hdr ?
-			  sctp_cname(SCTP_ST_CHUNK(chunk->chunk_hdr->type))
-			  : "Illegal Chunk");
+	pr_debug("%s: outq:%p, chunk:%p[%s]\n", __func__, q, chunk,
+		 chunk && chunk->chunk_hdr ?
+		 sctp_cname(SCTP_ST_CHUNK(chunk->chunk_hdr->type)) :
+		 "illegal chunk");
 
 	/* If it is data, queue it up, otherwise, send it
 	 * immediately.
@@ -328,10 +328,10 @@ int sctp_outq_tail(struct sctp_outq *q, struct sctp_chunk *chunk)
 			break;
 
 		default:
-			SCTP_DEBUG_PRINTK("outqueueing (%p, %p[%s])\n",
-			  q, chunk, chunk && chunk->chunk_hdr ?
-			  sctp_cname(SCTP_ST_CHUNK(chunk->chunk_hdr->type))
-			  : "Illegal Chunk");
+			pr_debug("%s: outqueueing: outq:%p, chunk:%p[%s])\n",
+				 __func__, q, chunk, chunk && chunk->chunk_hdr ?
+				 sctp_cname(SCTP_ST_CHUNK(chunk->chunk_hdr->type)) :
+				 "illegal chunk");
 
 			sctp_outq_tail_data(q, chunk);
 			if (chunk->chunk_hdr->flags & SCTP_DATA_UNORDERED)
@@ -460,14 +460,10 @@ void sctp_retransmit_mark(struct sctp_outq *q,
 		}
 	}
 
-	SCTP_DEBUG_PRINTK("%s: transport: %p, reason: %d, "
-			  "cwnd: %d, ssthresh: %d, flight_size: %d, "
-			  "pba: %d\n", __func__,
-			  transport, reason,
-			  transport->cwnd, transport->ssthresh,
-			  transport->flight_size,
-			  transport->partial_bytes_acked);
-
+	pr_debug("%s: transport:%p, reason:%d, cwnd:%d, ssthresh:%d, "
+		 "flight_size:%d, pba:%d\n", __func__, transport, reason,
+		 transport->cwnd, transport->ssthresh, transport->flight_size,
+		 transport->partial_bytes_acked);
 }
 
 /* Mark all the eligible packets on a transport for retransmission and force
@@ -1014,19 +1010,13 @@ static int sctp_outq_flush(struct sctp_outq *q, int rtx_timeout)
 				sctp_transport_burst_limited(transport);
 			}
 
-			SCTP_DEBUG_PRINTK("sctp_outq_flush(%p, %p[%s]), ",
-					  q, chunk,
-					  chunk && chunk->chunk_hdr ?
-					  sctp_cname(SCTP_ST_CHUNK(
-						  chunk->chunk_hdr->type))
-					  : "Illegal Chunk");
-
-			SCTP_DEBUG_PRINTK("TX TSN 0x%x skb->head "
-					"%p skb->users %d.\n",
-					ntohl(chunk->subh.data_hdr->tsn),
-					chunk->skb ?chunk->skb->head : NULL,
-					chunk->skb ?
-					atomic_read(&chunk->skb->users) : -1);
+			pr_debug("%s: outq:%p, chunk:%p[%s], tx-tsn:0x%x skb->head:%p "
+				 "skb->users:%d\n",
+				 __func__, q, chunk, chunk && chunk->chunk_hdr ?
+				 sctp_cname(SCTP_ST_CHUNK(chunk->chunk_hdr->type)) :
+				 "illegal chunk", ntohl(chunk->subh.data_hdr->tsn),
+				 chunk->skb ? chunk->skb->head : NULL, chunk->skb ?
+				 atomic_read(&chunk->skb->users) : -1);
 
 			/* Add the chunk to the packet.  */
 			status = sctp_packet_transmit_chunk(packet, chunk, 0);
@@ -1038,10 +1028,10 @@ static int sctp_outq_flush(struct sctp_outq *q, int rtx_timeout)
 				/* We could not append this chunk, so put
 				 * the chunk back on the output queue.
 				 */
-				SCTP_DEBUG_PRINTK("sctp_outq_flush: could "
-					"not transmit TSN: 0x%x, status: %d\n",
-					ntohl(chunk->subh.data_hdr->tsn),
-					status);
+				pr_debug("%s: could not transmit tsn:0x%x, status:%d\n",
+					 __func__, ntohl(chunk->subh.data_hdr->tsn),
+					 status);
+
 				sctp_outq_head_data(q, chunk);
 				goto sctp_flush_out;
 				break;
@@ -1284,11 +1274,10 @@ int sctp_outq_sack(struct sctp_outq *q, struct sctp_chunk *chunk)
 
 	sctp_generate_fwdtsn(q, sack_ctsn);
 
-	SCTP_DEBUG_PRINTK("%s: sack Cumulative TSN Ack is 0x%x.\n",
-			  __func__, sack_ctsn);
-	SCTP_DEBUG_PRINTK("%s: Cumulative TSN Ack of association, "
-			  "%p is 0x%x. Adv peer ack point: 0x%x\n",
-			  __func__, asoc, ctsn, asoc->adv_peer_ack_point);
+	pr_debug("%s: sack cumulative tsn ack:0x%x\n", __func__, sack_ctsn);
+	pr_debug("%s: cumulative tsn ack of assoc:%p is 0x%x, "
+		 "advertised peer ack point:0x%x\n", __func__, asoc, ctsn,
+		 asoc->adv_peer_ack_point);
 
 	/* See if all chunks are acked.
 	 * Make sure the empty queue handler will get run later.
@@ -1304,7 +1293,7 @@ int sctp_outq_sack(struct sctp_outq *q, struct sctp_chunk *chunk)
 			goto finish;
 	}
 
-	SCTP_DEBUG_PRINTK("sack queue is empty.\n");
+	pr_debug("%s: sack queue is empty\n", __func__);
 finish:
 	return q->empty;
 }
@@ -1348,7 +1337,7 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 
 	/* These state variables are for coherent debug output. --xguo */
 
-#if SCTP_DEBUG
+#ifdef CONFIG_SCTP_DBG_TSNS
 	__u32 dbg_ack_tsn = 0;	/* An ACKed TSN range starts here... */
 	__u32 dbg_last_ack_tsn = 0;  /* ...and finishes here.	     */
 	__u32 dbg_kept_tsn = 0;	/* An un-ACKed range starts here...  */
@@ -1359,7 +1348,7 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 	 * -1: We need to initialize.
 	 */
 	int dbg_prt_state = -1;
-#endif /* SCTP_DEBUG */
+#endif /* CONFIG_SCTP_DBG_TSNS */
 
 	sack_ctsn = ntohl(sack->cum_tsn_ack);
 
@@ -1483,7 +1472,7 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 				list_add_tail(lchunk, &tlist);
 			}
 
-#if SCTP_DEBUG
+#ifdef CONFIG_SCTP_DBG_TSNS
 			switch (dbg_prt_state) {
 			case 0:	/* last TSN was ACKed */
 				if (dbg_last_ack_tsn + 1 == tsn) {
@@ -1497,42 +1486,39 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 					/* Display the end of the
 					 * current range.
 					 */
-					SCTP_DEBUG_PRINTK_CONT("-%08x",
-							       dbg_last_ack_tsn);
+					pr_cont("-%08x", dbg_last_ack_tsn);
 				}
 
 				/* Start a new range.  */
-				SCTP_DEBUG_PRINTK_CONT(",%08x", tsn);
+				pr_cont(",%08x", tsn);
 				dbg_ack_tsn = tsn;
 				break;
 
 			case 1:	/* The last TSN was NOT ACKed. */
 				if (dbg_last_kept_tsn != dbg_kept_tsn) {
 					/* Display the end of current range. */
-					SCTP_DEBUG_PRINTK_CONT("-%08x",
-							       dbg_last_kept_tsn);
+					pr_cont("-%08x", dbg_last_kept_tsn);
 				}
 
-				SCTP_DEBUG_PRINTK_CONT("\n");
-
+				pr_cont("\n");
 				/* FALL THROUGH... */
 			default:
 				/* This is the first-ever TSN we examined.  */
 				/* Start a new range of ACK-ed TSNs.  */
-				SCTP_DEBUG_PRINTK("ACKed: %08x", tsn);
+				pr_debug("ACKed: %08x", tsn);
+
 				dbg_prt_state = 0;
 				dbg_ack_tsn = tsn;
 			}
 
 			dbg_last_ack_tsn = tsn;
-#endif /* SCTP_DEBUG */
+#endif /* CONFIG_SCTP_DBG_TSNS */
 
 		} else {
 			if (tchunk->tsn_gap_acked) {
-				SCTP_DEBUG_PRINTK("%s: Receiver reneged on "
-						  "data TSN: 0x%x\n",
-						  __func__,
-						  tsn);
+				pr_debug("%s: receiver reneged on data TSN:0x%x\n",
+					 __func__, tsn);
+
 				tchunk->tsn_gap_acked = 0;
 
 				if (tchunk->transport)
@@ -1552,7 +1538,7 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 
 			list_add_tail(lchunk, &tlist);
 
-#if SCTP_DEBUG
+#ifdef CONFIG_SCTP_DBG_TSNS
 			/* See the above comments on ACK-ed TSNs. */
 			switch (dbg_prt_state) {
 			case 1:
@@ -1560,50 +1546,47 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 					break;
 
 				if (dbg_last_kept_tsn != dbg_kept_tsn)
-					SCTP_DEBUG_PRINTK_CONT("-%08x",
-							       dbg_last_kept_tsn);
+					pr_cont("-%08x", dbg_last_kept_tsn);
 
-				SCTP_DEBUG_PRINTK_CONT(",%08x", tsn);
+				pr_cont(",%08x", tsn);
 				dbg_kept_tsn = tsn;
 				break;
 
 			case 0:
 				if (dbg_last_ack_tsn != dbg_ack_tsn)
-					SCTP_DEBUG_PRINTK_CONT("-%08x",
-							       dbg_last_ack_tsn);
-				SCTP_DEBUG_PRINTK_CONT("\n");
+					pr_cont("-%08x", dbg_last_ack_tsn);
 
+				pr_cont("\n");
 				/* FALL THROUGH... */
 			default:
-				SCTP_DEBUG_PRINTK("KEPT: %08x",tsn);
+				pr_debug("KEPT: %08x", tsn);
+
 				dbg_prt_state = 1;
 				dbg_kept_tsn = tsn;
 			}
 
 			dbg_last_kept_tsn = tsn;
-#endif /* SCTP_DEBUG */
+#endif /* CONFIG_SCTP_DBG_TSNS */
 		}
 	}
 
-#if SCTP_DEBUG
+#ifdef CONFIG_SCTP_DBG_TSNS
 	/* Finish off the last range, displaying its ending TSN.  */
 	switch (dbg_prt_state) {
 	case 0:
-		if (dbg_last_ack_tsn != dbg_ack_tsn) {
-			SCTP_DEBUG_PRINTK_CONT("-%08x\n", dbg_last_ack_tsn);
-		} else {
-			SCTP_DEBUG_PRINTK_CONT("\n");
-		}
-	break;
-
+		if (dbg_last_ack_tsn != dbg_ack_tsn)
+			pr_cont("-%08x\n", dbg_last_ack_tsn);
+		else
+			pr_cont("\n");
+		break;
 	case 1:
-		if (dbg_last_kept_tsn != dbg_kept_tsn) {
-			SCTP_DEBUG_PRINTK_CONT("-%08x\n", dbg_last_kept_tsn);
-		} else {
-			SCTP_DEBUG_PRINTK_CONT("\n");
-		}
+		if (dbg_last_kept_tsn != dbg_kept_tsn)
+			pr_cont("-%08x\n", dbg_last_kept_tsn);
+		else
+			pr_cont("\n");
+		break;
 	}
-#endif /* SCTP_DEBUG */
+#endif /* CONFIG_SCTP_DBG_TSNS */
 	if (transport) {
 		if (bytes_acked) {
 			struct sctp_association *asoc = transport->asoc;
@@ -1676,9 +1659,9 @@ static void sctp_check_transmitted(struct sctp_outq *q,
 			    !list_empty(&tlist) &&
 			    (sack_ctsn+2 == q->asoc->next_tsn) &&
 			    q->asoc->state < SCTP_STATE_SHUTDOWN_PENDING) {
-				SCTP_DEBUG_PRINTK("%s: SACK received for zero "
-						  "window probe: %u\n",
-						  __func__, sack_ctsn);
+				pr_debug("%s: sack received for zero window "
+					 "probe:%u\n", __func__, sack_ctsn);
+
 				q->asoc->overall_error_count = 0;
 				transport->error_count = 0;
 			}
@@ -1739,10 +1722,8 @@ static void sctp_mark_missing(struct sctp_outq *q,
 						count_of_newacks, tsn)) {
 				chunk->tsn_missing_report++;
 
-				SCTP_DEBUG_PRINTK(
-					"%s: TSN 0x%x missing counter: %d\n",
-					__func__, tsn,
-					chunk->tsn_missing_report);
+				pr_debug("%s: tsn:0x%x missing counter:%d\n",
+					 __func__, tsn, chunk->tsn_missing_report);
 			}
 		}
 		/*
@@ -1762,11 +1743,10 @@ static void sctp_mark_missing(struct sctp_outq *q,
 		if (do_fast_retransmit)
 			sctp_retransmit(q, transport, SCTP_RTXR_FAST_RTX);
 
-		SCTP_DEBUG_PRINTK("%s: transport: %p, cwnd: %d, "
-				  "ssthresh: %d, flight_size: %d, pba: %d\n",
-				  __func__, transport, transport->cwnd,
-				  transport->ssthresh, transport->flight_size,
-				  transport->partial_bytes_acked);
+		pr_debug("%s: transport:%p, cwnd:%d, ssthresh:%d, "
+			 "flight_size:%d, pba:%d\n",  __func__, transport,
+			 transport->cwnd, transport->ssthresh,
+			 transport->flight_size, transport->partial_bytes_acked);
 	}
 }