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/sm_statefuns.c b/net/sctp/sm_statefuns.c
index b3d1868..f6b7109 100644
--- a/net/sctp/sm_statefuns.c
+++ b/net/sctp/sm_statefuns.c
@@ -1179,9 +1179,9 @@
/* Check if the timestamp looks valid. */
if (time_after(hbinfo->sent_at, jiffies) ||
time_after(jiffies, hbinfo->sent_at + max_interval)) {
- SCTP_DEBUG_PRINTK("%s: HEARTBEAT ACK with invalid timestamp "
- "received for transport: %p\n",
- __func__, link);
+ pr_debug("%s: HEARTBEAT ACK with invalid timestamp received "
+ "for transport:%p\n", __func__, link);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -2562,7 +2562,8 @@
const struct sctp_association *asoc,
struct sctp_transport *transport)
{
- SCTP_DEBUG_PRINTK("ABORT received (INIT).\n");
+ pr_debug("%s: ABORT received (INIT)\n", __func__);
+
sctp_add_cmd_sf(commands, SCTP_CMD_NEW_STATE,
SCTP_STATE(SCTP_STATE_CLOSED));
SCTP_INC_STATS(net, SCTP_MIB_ABORTEDS);
@@ -2572,6 +2573,7 @@
/* CMD_INIT_FAILED will DELETE_TCB. */
sctp_add_cmd_sf(commands, SCTP_CMD_INIT_FAILED,
SCTP_PERR(error));
+
return SCTP_DISPOSITION_ABORT;
}
@@ -2637,8 +2639,9 @@
ctsn = ntohl(sdh->cum_tsn_ack);
if (TSN_lt(ctsn, asoc->ctsn_ack_point)) {
- SCTP_DEBUG_PRINTK("ctsn %x\n", ctsn);
- SCTP_DEBUG_PRINTK("ctsn_ack_point %x\n", asoc->ctsn_ack_point);
+ pr_debug("%s: ctsn:%x, ctsn_ack_point:%x\n", __func__, ctsn,
+ asoc->ctsn_ack_point);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -2721,8 +2724,9 @@
ctsn = ntohl(sdh->cum_tsn_ack);
if (TSN_lt(ctsn, asoc->ctsn_ack_point)) {
- SCTP_DEBUG_PRINTK("ctsn %x\n", ctsn);
- SCTP_DEBUG_PRINTK("ctsn_ack_point %x\n", asoc->ctsn_ack_point);
+ pr_debug("%s: ctsn:%x, ctsn_ack_point:%x\n", __func__, ctsn,
+ asoc->ctsn_ack_point);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -3174,8 +3178,9 @@
* Point indicates an out-of-order SACK.
*/
if (TSN_lt(ctsn, asoc->ctsn_ack_point)) {
- SCTP_DEBUG_PRINTK("ctsn %x\n", ctsn);
- SCTP_DEBUG_PRINTK("ctsn_ack_point %x\n", asoc->ctsn_ack_point);
+ pr_debug("%s: ctsn:%x, ctsn_ack_point:%x\n", __func__, ctsn,
+ asoc->ctsn_ack_point);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -3859,7 +3864,7 @@
skb_pull(chunk->skb, len);
tsn = ntohl(fwdtsn_hdr->new_cum_tsn);
- SCTP_DEBUG_PRINTK("%s: TSN 0x%x.\n", __func__, tsn);
+ pr_debug("%s: TSN 0x%x\n", __func__, tsn);
/* The TSN is too high--silently discard the chunk and count on it
* getting retransmitted later.
@@ -3927,7 +3932,7 @@
skb_pull(chunk->skb, len);
tsn = ntohl(fwdtsn_hdr->new_cum_tsn);
- SCTP_DEBUG_PRINTK("%s: TSN 0x%x.\n", __func__, tsn);
+ pr_debug("%s: TSN 0x%x\n", __func__, tsn);
/* The TSN is too high--silently discard the chunk and count on it
* getting retransmitted later.
@@ -4166,7 +4171,7 @@
struct sctp_chunk *err_chunk;
sctp_chunkhdr_t *hdr;
- SCTP_DEBUG_PRINTK("Processing the unknown chunk id %d.\n", type.chunk);
+ pr_debug("%s: processing unknown chunk id:%d\n", __func__, type.chunk);
if (!sctp_vtag_verify(unk_chunk, asoc))
return sctp_sf_pdiscard(net, ep, asoc, type, arg, commands);
@@ -4256,7 +4261,8 @@
return sctp_sf_violation_chunklen(net, ep, asoc, type, arg,
commands);
- SCTP_DEBUG_PRINTK("Chunk %d is discarded\n", type.chunk);
+ pr_debug("%s: chunk:%d is discarded\n", __func__, type.chunk);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -5184,7 +5190,9 @@
void *arg,
sctp_cmd_seq_t *commands)
{
- SCTP_DEBUG_PRINTK("Primitive type %d is ignored.\n", type.primitive);
+ pr_debug("%s: primitive type:%d is ignored\n", __func__,
+ type.primitive);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -5379,7 +5387,9 @@
void *arg,
sctp_cmd_seq_t *commands)
{
- SCTP_DEBUG_PRINTK("The event other type %d is ignored\n", type.other);
+ pr_debug("%s: the event other type:%d is ignored\n",
+ __func__, type.other);
+
return SCTP_DISPOSITION_DISCARD;
}
@@ -5527,7 +5537,8 @@
struct sctp_bind_addr *bp;
int attempts = asoc->init_err_counter + 1;
- SCTP_DEBUG_PRINTK("Timer T1 expired (INIT).\n");
+ pr_debug("%s: timer T1 expired (INIT)\n", __func__);
+
SCTP_INC_STATS(net, SCTP_MIB_T1_INIT_EXPIREDS);
if (attempts <= asoc->max_init_attempts) {
@@ -5546,9 +5557,10 @@
sctp_add_cmd_sf(commands, SCTP_CMD_REPLY, SCTP_CHUNK(repl));
} else {
- SCTP_DEBUG_PRINTK("Giving up on INIT, attempts: %d"
- " max_init_attempts: %d\n",
- attempts, asoc->max_init_attempts);
+ pr_debug("%s: giving up on INIT, attempts:%d "
+ "max_init_attempts:%d\n", __func__, attempts,
+ asoc->max_init_attempts);
+
sctp_add_cmd_sf(commands, SCTP_CMD_SET_SK_ERR,
SCTP_ERROR(ETIMEDOUT));
sctp_add_cmd_sf(commands, SCTP_CMD_INIT_FAILED,
@@ -5588,7 +5600,8 @@
struct sctp_chunk *repl = NULL;
int attempts = asoc->init_err_counter + 1;
- SCTP_DEBUG_PRINTK("Timer T1 expired (COOKIE-ECHO).\n");
+ pr_debug("%s: timer T1 expired (COOKIE-ECHO)\n", __func__);
+
SCTP_INC_STATS(net, SCTP_MIB_T1_COOKIE_EXPIREDS);
if (attempts <= asoc->max_init_attempts) {
@@ -5636,7 +5649,8 @@
{
struct sctp_chunk *reply = NULL;
- SCTP_DEBUG_PRINTK("Timer T2 expired.\n");
+ pr_debug("%s: timer T2 expired\n", __func__);
+
SCTP_INC_STATS(net, SCTP_MIB_T2_SHUTDOWN_EXPIREDS);
((struct sctp_association *)asoc)->shutdown_retries++;
@@ -5777,7 +5791,8 @@
{
struct sctp_chunk *reply = NULL;
- SCTP_DEBUG_PRINTK("Timer T5 expired.\n");
+ pr_debug("%s: timer T5 expired\n", __func__);
+
SCTP_INC_STATS(net, SCTP_MIB_T5_SHUTDOWN_GUARD_EXPIREDS);
reply = sctp_make_abort(asoc, NULL, 0);
@@ -5892,7 +5907,8 @@
void *arg,
sctp_cmd_seq_t *commands)
{
- SCTP_DEBUG_PRINTK("Timer %d ignored.\n", type.chunk);
+ pr_debug("%s: timer %d ignored\n", __func__, type.chunk);
+
return SCTP_DISPOSITION_CONSUME;
}
@@ -6102,7 +6118,7 @@
skb_pull(chunk->skb, sizeof(sctp_datahdr_t));
tsn = ntohl(data_hdr->tsn);
- SCTP_DEBUG_PRINTK("eat_data: TSN 0x%x.\n", tsn);
+ pr_debug("%s: TSN 0x%x\n", __func__, tsn);
/* ASSERT: Now skb->data is really the user data. */
@@ -6179,12 +6195,12 @@
*/
if (sctp_tsnmap_has_gap(map) &&
(sctp_tsnmap_get_ctsn(map) + 1) == tsn) {
- SCTP_DEBUG_PRINTK("Reneging for tsn:%u\n", tsn);
+ pr_debug("%s: reneging for tsn:%u\n", __func__, tsn);
deliver = SCTP_CMD_RENEGE;
} else {
- SCTP_DEBUG_PRINTK("Discard tsn: %u len: %Zd, "
- "rwnd: %d\n", tsn, datalen,
- asoc->rwnd);
+ pr_debug("%s: discard tsn:%u len:%zu, rwnd:%d\n",
+ __func__, tsn, datalen, asoc->rwnd);
+
return SCTP_IERROR_IGNORE_TSN;
}
}
@@ -6199,7 +6215,8 @@
if (*sk->sk_prot_creator->memory_pressure) {
if (sctp_tsnmap_has_gap(map) &&
(sctp_tsnmap_get_ctsn(map) + 1) == tsn) {
- SCTP_DEBUG_PRINTK("Under Pressure! Reneging for tsn:%u\n", tsn);
+ pr_debug("%s: under pressure, reneging for tsn:%u\n",
+ __func__, tsn);
deliver = SCTP_CMD_RENEGE;
}
}