> -----Original Message-----
> From: Hoang Le <hoang.h...@dektech.com.au>
> Sent: September 27, 2018 5:04 AM
> To: tipc-discussion@lists.sourceforge.net; Jon Maloy
> <jon.ma...@ericsson.com>; ma...@donjonn.com; ying....@windriver.com
> Subject: [net-next] tipc:add more debug printouts
>
> 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
> @@ -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;
>
> - 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);
You should try to make this even more compact. Printouts take up both CPU
cycles and space in the log files.
E.g., There is no need to print out the whole link name, just the part after
the "-". We know which node the printout comes from anyway.
Something like this:
pr_debug(" Link %s FSM: %x->(%x)->%x\n", strchr('-', l->name), l->state, evt,
state);
> + 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);
I think we need a separate message printout function that print the message in
a compact form into a char string. It then returns the string to be printed out
by pr_debug.
E.g:
char msgbuf[128];
......
pr_debug("%s: validation failed for %s\n",
strchar('-', l->name, pr_msg(msgbuf, hdr));
> 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));
Same comment as above: Use generic message printout function, link state
function, node state function, socket state function etc, and let pr_debug
print out the returned strings.
BR
///jon
> 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)));
> 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