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>
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 @@
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 @@
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 @@
}
}
- 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 @@
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 @@
/* 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 @@
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 @@
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 @@
/* 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 @@
* -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 @@
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 @@
/* 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 @@
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 @@
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 @@
!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 @@
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 @@
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);
}
}