Hi Hoang,
In general I feel that you should avoild using pr_debug when the
information belongs to per socket. For sockets use tracepoints (
https://lwn.net/Articles/379903/) or atleast the ratelimited variants.
See my comments below.
On Thu, Sep 27, 2018 at 11:04 AM Hoang Le <hoang.h...@dektech.com.au> wrote:
> It is useful when using dynamic debug (dyndbg) to turn on/off
> debug printouts.
> In this commit, we provide as much as possible debug information
> that we used to troubleshoot issues in our lab.
>
> Signed-off-by: Hoang Le <hoang.h...@dektech.com.au>
> ---
> net/tipc/bearer.c | 3 +++
> net/tipc/link.c | 68 ++++++++++++++++++++++++++++++++++-------------
> net/tipc/link.h | 4 +++
> net/tipc/node.c | 14 ++++++++--
> net/tipc/socket.c | 34 ++++++++++++++++++++++--
> 5 files changed, 100 insertions(+), 23 deletions(-)
>
> diff --git a/net/tipc/bearer.c b/net/tipc/bearer.c
> index 91891041e5e1..1ad49f14c129 100644
> --- a/net/tipc/bearer.c
> +++ b/net/tipc/bearer.c
[partha] To get the module name prefixed in the print, you add the line
below as the first line in the C file:
#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt
> @@ -607,6 +607,9 @@ static int tipc_l2_device_event(struct notifier_block
> *nb, unsigned long evt,
> if (!b)
> return NOTIFY_DONE;
>
> + pr_debug("Bearer %s got event %lu from dev %s, status %lu,
> carrier:%d\n",
> + b->name, evt, dev->name, b->up, netif_carrier_ok(dev));
> +
> switch (evt) {
> case NETDEV_CHANGE:
> if (netif_carrier_ok(dev))
> diff --git a/net/tipc/link.c b/net/tipc/link.c
> index b1f0bee54eac..25bed78816d0 100644
> --- a/net/tipc/link.c
> +++ b/net/tipc/link.c
> @@ -542,15 +542,16 @@ bool tipc_link_bc_create(struct net *net, u32
> ownnode, u32 peer,
> int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> {
> int rc = 0;
> + int state = l->state;
[partha] int old_state = l->state;
>
> - switch (l->state) {
> + switch (state) {
> case LINK_RESETTING:
> switch (evt) {
> case LINK_PEER_RESET_EVT:
> - l->state = LINK_PEER_RESET;
> + state = LINK_PEER_RESET;
> break;
> case LINK_RESET_EVT:
> - l->state = LINK_RESET;
> + state = LINK_RESET;
> break;
> case LINK_FAILURE_EVT:
> case LINK_FAILOVER_BEGIN_EVT:
> @@ -565,10 +566,10 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> case LINK_RESET:
> switch (evt) {
> case LINK_PEER_RESET_EVT:
> - l->state = LINK_ESTABLISHING;
> + state = LINK_ESTABLISHING;
> break;
> case LINK_FAILOVER_BEGIN_EVT:
> - l->state = LINK_FAILINGOVER;
> + state = LINK_FAILINGOVER;
> case LINK_FAILURE_EVT:
> case LINK_RESET_EVT:
> case LINK_ESTABLISH_EVT:
> @@ -583,7 +584,7 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> case LINK_PEER_RESET:
> switch (evt) {
> case LINK_RESET_EVT:
> - l->state = LINK_ESTABLISHING;
> + state = LINK_ESTABLISHING;
> break;
> case LINK_PEER_RESET_EVT:
> case LINK_ESTABLISH_EVT:
> @@ -600,7 +601,7 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> case LINK_FAILINGOVER:
> switch (evt) {
> case LINK_FAILOVER_END_EVT:
> - l->state = LINK_RESET;
> + state = LINK_RESET;
> break;
> case LINK_PEER_RESET_EVT:
> case LINK_RESET_EVT:
> @@ -617,13 +618,13 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> case LINK_ESTABLISHING:
> switch (evt) {
> case LINK_ESTABLISH_EVT:
> - l->state = LINK_ESTABLISHED;
> + state = LINK_ESTABLISHED;
> break;
> case LINK_FAILOVER_BEGIN_EVT:
> - l->state = LINK_FAILINGOVER;
> + state = LINK_FAILINGOVER;
> break;
> case LINK_RESET_EVT:
> - l->state = LINK_RESET;
> + state = LINK_RESET;
> break;
> case LINK_FAILURE_EVT:
> case LINK_PEER_RESET_EVT:
> @@ -638,21 +639,21 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> case LINK_ESTABLISHED:
> switch (evt) {
> case LINK_PEER_RESET_EVT:
> - l->state = LINK_PEER_RESET;
> + state = LINK_PEER_RESET;
> rc |= TIPC_LINK_DOWN_EVT;
> break;
> case LINK_FAILURE_EVT:
> - l->state = LINK_RESETTING;
> + state = LINK_RESETTING;
> rc |= TIPC_LINK_DOWN_EVT;
> break;
> case LINK_RESET_EVT:
> - l->state = LINK_RESET;
> + state = LINK_RESET;
> break;
> case LINK_ESTABLISH_EVT:
> case LINK_SYNCH_END_EVT:
> break;
> case LINK_SYNCH_BEGIN_EVT:
> - l->state = LINK_SYNCHING;
> + state = LINK_SYNCHING;
> break;
> case LINK_FAILOVER_BEGIN_EVT:
> case LINK_FAILOVER_END_EVT:
> @@ -663,21 +664,21 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> case LINK_SYNCHING:
> switch (evt) {
> case LINK_PEER_RESET_EVT:
> - l->state = LINK_PEER_RESET;
> + state = LINK_PEER_RESET;
> rc |= TIPC_LINK_DOWN_EVT;
> break;
> case LINK_FAILURE_EVT:
> - l->state = LINK_RESETTING;
> + state = LINK_RESETTING;
> rc |= TIPC_LINK_DOWN_EVT;
> break;
> case LINK_RESET_EVT:
> - l->state = LINK_RESET;
> + state = LINK_RESET;
> break;
> case LINK_ESTABLISH_EVT:
> case LINK_SYNCH_BEGIN_EVT:
> break;
> case LINK_SYNCH_END_EVT:
> - l->state = LINK_ESTABLISHED;
> + state = LINK_ESTABLISHED;
> break;
> case LINK_FAILOVER_BEGIN_EVT:
> case LINK_FAILOVER_END_EVT:
> @@ -688,6 +689,9 @@ int tipc_link_fsm_evt(struct tipc_link *l, int evt)
> default:
> pr_err("Unknown FSM state %x in %s\n", l->state, l->name);
> }
> + pr_debug("Link %s change state (0x%x)=>(0x%x), evt 0x%x\n",
> + l->name, l->state, state, evt);
>
[partha] Your change for l->state and state seems unnecessary. Why don't
you store the old state and let l->state remain as it is like:
[partha] pr_debug("Link %s change state (0x%x)=>(0x%x), evt 0x%x\n",
l->name, old_state, l->state, evt);
> + l->state = state;
>
return rc;
> illegal_evt:
> pr_err("Illegal FSM event %x in state %x on link %s\n",
> @@ -1518,8 +1522,13 @@ static int tipc_link_proto_rcv(struct tipc_link *l,
> struct sk_buff *skb,
> hdr = buf_msg(skb);
> data = msg_data(hdr);
>
> - if (!tipc_link_validate_msg(l, hdr))
> + if (!tipc_link_validate_msg(l, hdr)) {
> + pr_debug("Link %s reject msg seqno %d, usr %d, mtype,
> state %d, peer_session %u, session %u, rcv_nxt_state %u\n",
> + msg_seqno(hdr), msg_user(hdr), mtyp, l->state,
> + l->peer_session, msg_session(hdr),
> + l->rcv_nxt_state);
> goto exit;
> + }
>
> switch (mtyp) {
> case RESET_MSG:
> @@ -2195,3 +2204,24 @@ void tipc_link_set_abort_limit(struct tipc_link *l,
> u32 limit)
> {
> l->abort_limit = limit;
> }
> +
> +int tipc_link_state(struct tipc_link *l)
> +{
> + return l->state;
> +}
> +
> +int tipc_link_peer_session(struct tipc_link *l)
> +{
> + return l->peer_session;
> +}
> +
> +u16 tipc_link_rcv_next_state(struct tipc_link *l)
> +{
> + return l->rcv_nxt_state;
> +}
> +
> +u16 tipc_link_snd_next_state(struct tipc_link *l)
> +{
> + return l->snd_nxt_state;
> +}
> +
> diff --git a/net/tipc/link.h b/net/tipc/link.h
> index 7bc494a33fdf..e1d3a334eb7c 100644
> --- a/net/tipc/link.h
> +++ b/net/tipc/link.h
> @@ -144,4 +144,8 @@ int tipc_link_bc_sync_rcv(struct tipc_link *l,
> struct tipc_msg *hdr,
> struct sk_buff_head *xmitq);
> int tipc_link_bc_nack_rcv(struct tipc_link *l, struct sk_buff *skb,
> struct sk_buff_head *xmitq);
> +int tipc_link_state(struct tipc_link *l);
> +int tipc_link_peer_session(struct tipc_link *l);
> +u16 tipc_link_rcv_next_state(struct tipc_link *l);
> +u16 tipc_link_snd_next_state(struct tipc_link *l);
> #endif
> diff --git a/net/tipc/node.c b/net/tipc/node.c
> index 68014f1b6976..69389c67f88a 100644
> --- a/net/tipc/node.c
> +++ b/net/tipc/node.c
> @@ -1222,6 +1222,8 @@ static void tipc_node_fsm_evt(struct tipc_node *n,
> int evt)
> pr_err("Unknown node fsm state %x\n", state);
> break;
> }
> + pr_debug("Node %x change state (0x%x)=>(0x%x), evt 0x%x\n",
> + n->addr, n->state, state, evt);
> n->state = state;
> return;
>
> @@ -1567,8 +1569,12 @@ static bool tipc_node_check_state(struct tipc_node
> *n, struct sk_buff *skb,
> l = n->links[bearer_id].link;
> if (!l)
> return false;
> - rcv_nxt = tipc_link_rcv_nxt(l);
>
> + pr_debug("Node %x, nstate:0x%x, link:%s, lstate:0x%x, usr:%d,
> mtype: %d\n",
> + n->addr, state, tipc_link_name(l), tipc_link_state(l),
> + usr, mtyp);
> +
> + rcv_nxt = tipc_link_rcv_nxt(l);
>
> if (likely((state == SELF_UP_PEER_UP) && (usr != TUNNEL_PROTOCOL)))
> return true;
> @@ -1581,8 +1587,12 @@ static bool tipc_node_check_state(struct tipc_node
> *n, struct sk_buff *skb,
> }
> }
>
> - if (!tipc_link_validate_msg(l, hdr))
> + if (!tipc_link_validate_msg(l, hdr)) {
> + pr_debug("Reject msg seqno %d, lpeer_session %u, session
> %u, lrcv_nxt_state %u\n",
> + oseqno, tipc_link_peer_session(l),
> msg_session(hdr),
> + tipc_link_rcv_next_state(l));
> return false;
> + }
>
> /* Check and update node accesibility if applicable */
> if (state == SELF_UP_PEER_COMING) {
> diff --git a/net/tipc/socket.c b/net/tipc/socket.c
> index 3f03ddd0e35b..468748a7f3dc 100644
> --- a/net/tipc/socket.c
> +++ b/net/tipc/socket.c
> @@ -262,8 +262,13 @@ static void tsk_rej_rx_queue(struct sock *sk)
> {
> struct sk_buff *skb;
>
> - while ((skb = __skb_dequeue(&sk->sk_receive_queue)))
> + while ((skb = __skb_dequeue(&sk->sk_receive_queue))) {
> + pr_debug("Reject msg seqno %d from node %x, port %u, err
> NO_PORT\n",
> + msg_seqno(buf_msg(skb)),
> + msg_prevnode(buf_msg(skb)),
> + msg_origport(buf_msg(skb)));
> tipc_sk_respond(sk, skb, TIPC_ERR_NO_PORT);
> + }
> }
>
> static bool tipc_sk_connected(struct sock *sk)
> @@ -520,6 +525,9 @@ static void __tipc_shutdown(struct socket *sock, int
> error)
> tipc_set_sk_state(sk, TIPC_DISCONNECTING);
> tipc_node_remove_conn(net, dnode, tsk->portid);
> }
> + pr_debug("Reject msg seqno %d from node %x, port %u, err
> %d\n",
> + msg_seqno(buf_msg(skb)),
> msg_prevnode(buf_msg(skb)),
> + msg_origport(buf_msg(skb)), error);
> tipc_sk_respond(sk, skb, error);
> }
>
> @@ -1205,10 +1213,16 @@ static void tipc_sk_conn_proto_rcv(struct
> tipc_sock *tsk, struct sk_buff *skb,
> bool conn_cong;
>
> /* Ignore if connection cannot be validated: */
> - if (!tsk_peer_msg(tsk, hdr))
> + if (!tsk_peer_msg(tsk, hdr)) {
> + pr_debug("Drop mtype %u from node %x, port %u\n", mtyp,
> + msg_prevnode(hdr), msg_origport(hdr));
> goto exit;
> + }
>
> if (unlikely(msg_errcode(hdr))) {
> + pr_debug("Drop mtype %u from node %x, port %u, err %d\n",
> + mtyp, msg_prevnode(hdr), msg_origport(hdr),
> + msg_errcode(hdr));
> tipc_set_sk_state(sk, TIPC_DISCONNECTING);
> tipc_node_remove_conn(sock_net(sk), tsk_peer_node(tsk),
> tsk_peer_port(tsk));
> @@ -1219,6 +1233,8 @@ static void tipc_sk_conn_proto_rcv(struct tipc_sock
> *tsk, struct sk_buff *skb,
> tsk->probe_unacked = false;
>
> if (mtyp == CONN_PROBE) {
> + pr_debug("Reply PROBE seq %u to node %d, port %d\n",
> + msg_seqno(hdr), msg_prevnode(hdr),
> msg_origport(hdr));
> msg_set_type(hdr, CONN_PROBE_REPLY);
> if (tipc_msg_reverse(onode, &skb, TIPC_OK))
> __skb_queue_tail(xmitq, skb);
> @@ -1949,6 +1965,8 @@ static void tipc_sk_proto_rcv(struct sock *sk,
> hdr, inputq, xmitq);
> break;
> default:
> + pr_debug("Drop msg, user %d from node %x, port %u\n",
> + msg_user(hdr), msg_prevnode(hdr),
> msg_origport(hdr));
> break;
> }
>
> @@ -2127,6 +2145,9 @@ static void tipc_sk_filter_rcv(struct sock *sk,
> struct sk_buff *skb,
> }
>
> if (unlikely(err)) {
> + pr_debug("Reject msg from node %x, port %d, err
> %d\n",
> + msg_prevnode(buf_msg(skb)),
> + msg_origport(buf_msg(skb)), err);
> tipc_skb_reject(net, err, skb, xmitq);
> err = TIPC_OK;
> continue;
> @@ -2204,6 +2225,10 @@ static void tipc_sk_enqueue(struct sk_buff_head
> *inputq, struct sock *sk,
> /* Overload => reject message back to sender */
> onode = tipc_own_addr(sock_net(sk));
> atomic_inc(&sk->sk_drops);
> + pr_debug("Reject msg seqno %d from node %d, port %u, err
> OVERLOAD\n",
> + msg_seqno(buf_msg(skb)),
> + msg_prevnode(buf_msg(skb)),
> + msg_origport(buf_msg(skb)));
>
Using pr_debug for message overflow per socket is dangerous. If at all this
is needed, you should use pr_debug_ratelimited().
> if (tipc_msg_reverse(onode, &skb, TIPC_ERR_OVERLOAD))
> __skb_queue_tail(xmitq, skb);
> break;
> @@ -2251,6 +2276,11 @@ void tipc_sk_rcv(struct net *net, struct
> sk_buff_head *inputq)
> if (tipc_msg_lookup_dest(net, skb, &err))
> goto xmit;
>
> + pr_debug("Reject msg seqno %d from node %x, port %u, err
> NO_PORT\n",
> + msg_seqno(buf_msg(skb)),
> + msg_prevnode(buf_msg(skb)),
> + msg_origport(buf_msg(skb)));
> +
> /* Prepare for message rejection */
> if (!tipc_msg_reverse(tipc_own_addr(net), &skb, err))
> continue;
> --
> 2.17.1
>
>
>
> _______________________________________________
> tipc-discussion mailing list
> tipc-discussion@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>
_______________________________________________
tipc-discussion mailing list
tipc-discussion@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/tipc-discussion
