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_sideeffect.c b/net/sctp/sm_sideeffect.c
index ff91f47..cf6f845 100644
--- a/net/sctp/sm_sideeffect.c
+++ b/net/sctp/sm_sideeffect.c
@@ -257,7 +257,7 @@
sctp_bh_lock_sock(asoc->base.sk);
if (sock_owned_by_user(asoc->base.sk)) {
- SCTP_DEBUG_PRINTK("%s:Sock is busy.\n", __func__);
+ pr_debug("%s: sock is busy\n", __func__);
/* Try again later. */
if (!mod_timer(&transport->T3_rtx_timer, jiffies + (HZ/20)))
@@ -297,9 +297,8 @@
sctp_bh_lock_sock(asoc->base.sk);
if (sock_owned_by_user(asoc->base.sk)) {
- SCTP_DEBUG_PRINTK("%s:Sock is busy: timer %d\n",
- __func__,
- timeout_type);
+ pr_debug("%s: sock is busy: timer %d\n", __func__,
+ timeout_type);
/* Try again later. */
if (!mod_timer(&asoc->timers[timeout_type], jiffies + (HZ/20)))
@@ -377,7 +376,7 @@
sctp_bh_lock_sock(asoc->base.sk);
if (sock_owned_by_user(asoc->base.sk)) {
- SCTP_DEBUG_PRINTK("%s:Sock is busy.\n", __func__);
+ pr_debug("%s: sock is busy\n", __func__);
/* Try again later. */
if (!mod_timer(&transport->hb_timer, jiffies + (HZ/20)))
@@ -415,7 +414,7 @@
sctp_bh_lock_sock(asoc->base.sk);
if (sock_owned_by_user(asoc->base.sk)) {
- SCTP_DEBUG_PRINTK("%s:Sock is busy.\n", __func__);
+ pr_debug("%s: sock is busy\n", __func__);
/* Try again later. */
if (!mod_timer(&transport->proto_unreach_timer,
@@ -521,11 +520,9 @@
if (transport->state != SCTP_INACTIVE &&
(transport->error_count > transport->pathmaxrxt)) {
- SCTP_DEBUG_PRINTK_IPADDR("transport_strike:association %p",
- " transport IP: port:%d failed.\n",
- asoc,
- (&transport->ipaddr),
- ntohs(transport->ipaddr.v4.sin_port));
+ pr_debug("%s: association:%p transport addr:%pISpc failed\n",
+ __func__, asoc, &transport->ipaddr.sa);
+
sctp_assoc_control_transport(asoc, transport,
SCTP_TRANSPORT_DOWN,
SCTP_FAILED_THRESHOLD);
@@ -804,8 +801,7 @@
asoc->state = state;
- SCTP_DEBUG_PRINTK("sctp_cmd_new_state: asoc %p[%s]\n",
- asoc, sctp_state_tbl[state]);
+ pr_debug("%s: asoc:%p[%s]\n", __func__, asoc, sctp_state_tbl[state]);
if (sctp_style(sk, TCP)) {
/* Change the sk->sk_state of a TCP-style socket that has
@@ -1017,15 +1013,11 @@
asoc->timeouts[timer] = asoc->max_init_timeo;
}
asoc->init_cycle++;
- SCTP_DEBUG_PRINTK(
- "T1 %s Timeout adjustment"
- " init_err_counter: %d"
- " cycle: %d"
- " timeout: %ld\n",
- name,
- asoc->init_err_counter,
- asoc->init_cycle,
- asoc->timeouts[timer]);
+
+ pr_debug("%s: T1[%s] timeout adjustment init_err_counter:%d"
+ " cycle:%d timeout:%ld\n", __func__, name,
+ asoc->init_err_counter, asoc->init_cycle,
+ asoc->timeouts[timer]);
}
}
@@ -1080,23 +1072,19 @@
* main flow of sctp_do_sm() to keep attention focused on the real
* functionality there.
*/
-#define DEBUG_PRE \
- SCTP_DEBUG_PRINTK("sctp_do_sm prefn: " \
- "ep %p, %s, %s, asoc %p[%s], %s\n", \
- ep, sctp_evttype_tbl[event_type], \
- (*debug_fn)(subtype), asoc, \
- sctp_state_tbl[state], state_fn->name)
+#define debug_pre_sfn() \
+ pr_debug("%s[pre-fn]: ep:%p, %s, %s, asoc:%p[%s], %s\n", __func__, \
+ ep, sctp_evttype_tbl[event_type], (*debug_fn)(subtype), \
+ asoc, sctp_state_tbl[state], state_fn->name)
-#define DEBUG_POST \
- SCTP_DEBUG_PRINTK("sctp_do_sm postfn: " \
- "asoc %p, status: %s\n", \
- asoc, sctp_status_tbl[status])
+#define debug_post_sfn() \
+ pr_debug("%s[post-fn]: asoc:%p, status:%s\n", __func__, asoc, \
+ sctp_status_tbl[status])
-#define DEBUG_POST_SFX \
- SCTP_DEBUG_PRINTK("sctp_do_sm post sfx: error %d, asoc %p[%s]\n", \
- error, asoc, \
- sctp_state_tbl[(asoc && sctp_id2assoc(ep->base.sk, \
- sctp_assoc2id(asoc)))?asoc->state:SCTP_STATE_CLOSED])
+#define debug_post_sfx() \
+ pr_debug("%s[post-sfx]: error:%d, asoc:%p[%s]\n", __func__, error, \
+ asoc, sctp_state_tbl[(asoc && sctp_id2assoc(ep->base.sk, \
+ sctp_assoc2id(asoc))) ? asoc->state : SCTP_STATE_CLOSED])
/*
* This is the master state machine processing function.
@@ -1116,7 +1104,6 @@
sctp_disposition_t status;
int error = 0;
typedef const char *(printfn_t)(sctp_subtype_t);
-
static printfn_t *table[] = {
NULL, sctp_cname, sctp_tname, sctp_oname, sctp_pname,
};
@@ -1129,21 +1116,18 @@
sctp_init_cmd_seq(&commands);
- DEBUG_PRE;
+ debug_pre_sfn();
status = (*state_fn->fn)(net, ep, asoc, subtype, event_arg, &commands);
- DEBUG_POST;
+ debug_post_sfn();
error = sctp_side_effects(event_type, subtype, state,
ep, asoc, event_arg, status,
&commands, gfp);
- DEBUG_POST_SFX;
+ debug_post_sfx();
return error;
}
-#undef DEBUG_PRE
-#undef DEBUG_POST
-
/*****************************************************************
* This the master state function side effect processing function.
*****************************************************************/
@@ -1172,9 +1156,9 @@
switch (status) {
case SCTP_DISPOSITION_DISCARD:
- SCTP_DEBUG_PRINTK("Ignored sctp protocol event - state %d, "
- "event_type %d, event_id %d\n",
- state, event_type, subtype.chunk);
+ pr_debug("%s: ignored sctp protocol event - state:%d, "
+ "event_type:%d, event_id:%d\n", __func__, state,
+ event_type, subtype.chunk);
break;
case SCTP_DISPOSITION_NOMEM:
@@ -1425,18 +1409,18 @@
case SCTP_CMD_CHUNK_ULP:
/* Send a chunk to the sockets layer. */
- SCTP_DEBUG_PRINTK("sm_sideff: %s %p, %s %p.\n",
- "chunk_up:", cmd->obj.chunk,
- "ulpq:", &asoc->ulpq);
+ pr_debug("%s: sm_sideff: chunk_up:%p, ulpq:%p\n",
+ __func__, cmd->obj.chunk, &asoc->ulpq);
+
sctp_ulpq_tail_data(&asoc->ulpq, cmd->obj.chunk,
GFP_ATOMIC);
break;
case SCTP_CMD_EVENT_ULP:
/* Send a notification to the sockets layer. */
- SCTP_DEBUG_PRINTK("sm_sideff: %s %p, %s %p.\n",
- "event_up:",cmd->obj.ulpevent,
- "ulpq:",&asoc->ulpq);
+ pr_debug("%s: sm_sideff: event_up:%p, ulpq:%p\n",
+ __func__, cmd->obj.ulpevent, &asoc->ulpq);
+
sctp_ulpq_tail_event(&asoc->ulpq, cmd->obj.ulpevent);
break;
@@ -1601,7 +1585,7 @@
break;
case SCTP_CMD_REPORT_BAD_TAG:
- SCTP_DEBUG_PRINTK("vtag mismatch!\n");
+ pr_debug("%s: vtag mismatch!\n", __func__);
break;
case SCTP_CMD_STRIKE: