Skip to content

Commit

Permalink
mptcp: pr_debug: add missing \n at the end
Browse files Browse the repository at this point in the history 
pr_debug() have been added in various places in MPTCP code to help
developers to debug some situations. With the dynamic debug feature, it
is easy to enable all or some of them, and asks users to reproduce
issues with extra debug.

Many of these pr_debug() don't end with a new line, while no 'pr_cont()'
are used in MPTCP code. So the goal was not to display multiple debug
messages on one line: they were then not missing the '\n' on purpose.
Not having the new line at the end causes these messages to be printed
with a delay, when something else needs to be printed. This issue is not
visible when many messages need to be printed, but it is annoying and
confusing when only specific messages are expected, e.g.

  # echo "func mptcp_pm_add_addr_echoed +fmp" > /sys/kernel/debug/dynamic_debug/control
  # ./mptcp_join.sh "signal address"; \
        echo "$(awk '{print $1}' /proc/uptime) - end"; \
        sleep 5s; \
        echo "$(awk '{print $1}' /proc/uptime) - restart"; \
        ./mptcp_join.sh "signal address"
  013 signal address
      (...)
  551.75 - end
  556.76 - restart
  013 signal address
  [  551.367935] mptcp:mptcp_pm_add_addr_echoed: MPTCP: msk=000000000740d23c
      (...)

  ## => a delay of 5 seconds.

The 'Fixes' tag here below points to the first pr_debug() used without
'\n' in net/mptcp. This patch could be split in many small ones, with
different Fixes tag, but it doesn't seem worth it, because it is easy to
re-generate this patch with this simple 'sed' command:

  git grep -l pr_debug -- net/mptcp |
    xargs sed -i "s/\(pr_debug(\".*[^n]\)\(\"[,)]\)/\1\\\n\2/g"

So in case of conflicts, simply drop the modifications, and launch this
command.

Fixes: f870fa0 ("mptcp: Add MPTCP socket stubs")
Signed-off-by: Matthieu Baerts (NGI0) <[email protected]>
  • Loading branch information
@matttbe @intel-lab-lkp
matttbe authored and intel-lab-lkp committed Aug 19, 2024
1 parent 45fdbcb commit 2fe0d6d
Show file tree
Hide file tree
Showing 9 changed files with 107 additions and 107 deletions.
4 changes: 2 additions & 2 deletions net/mptcp/fastopen.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -68,12 +68,12 @@ void __mptcp_fastopen_gen_msk_ackseq(struct mptcp_sock *msk, struct mptcp_subflo
skb = skb_peek_tail(&sk->sk_receive_queue);
if (skb) {
WARN_ON_ONCE(MPTCP_SKB_CB(skb)->end_seq);
pr_debug("msk %p moving seq %llx -> %llx end_seq %llx -> %llx", sk,
pr_debug("msk %p moving seq %llx -> %llx end_seq %llx -> %llx\n", sk,
MPTCP_SKB_CB(skb)->map_seq, MPTCP_SKB_CB(skb)->map_seq + msk->ack_seq,
MPTCP_SKB_CB(skb)->end_seq, MPTCP_SKB_CB(skb)->end_seq + msk->ack_seq);
MPTCP_SKB_CB(skb)->map_seq += msk->ack_seq;
MPTCP_SKB_CB(skb)->end_seq += msk->ack_seq;
}

pr_debug("msk=%p ack_seq=%llx", msk, msk->ack_seq);
pr_debug("msk=%p ack_seq=%llx\n", msk, msk->ack_seq);
}
50 changes: 25 additions & 25 deletions net/mptcp/options.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -117,7 +117,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
mp_opt->suboptions |= OPTION_MPTCP_CSUMREQD;
ptr += 2;
}
pr_debug("MP_CAPABLE version=%x, flags=%x, optlen=%d sndr=%llu, rcvr=%llu len=%d csum=%u",
pr_debug("MP_CAPABLE version=%x, flags=%x, optlen=%d sndr=%llu, rcvr=%llu len=%d csum=%u\n",
version, flags, opsize, mp_opt->sndr_key,
mp_opt->rcvr_key, mp_opt->data_len, mp_opt->csum);
break;
Expand All @@ -131,7 +131,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
ptr += 4;
mp_opt->nonce = get_unaligned_be32(ptr);
ptr += 4;
pr_debug("MP_JOIN bkup=%u, id=%u, token=%u, nonce=%u",
pr_debug("MP_JOIN bkup=%u, id=%u, token=%u, nonce=%u\n",
mp_opt->backup, mp_opt->join_id,
mp_opt->token, mp_opt->nonce);
} else if (opsize == TCPOLEN_MPTCP_MPJ_SYNACK) {
Expand All @@ -142,19 +142,19 @@ static void mptcp_parse_option(const struct sk_buff *skb,
ptr += 8;
mp_opt->nonce = get_unaligned_be32(ptr);
ptr += 4;
pr_debug("MP_JOIN bkup=%u, id=%u, thmac=%llu, nonce=%u",
pr_debug("MP_JOIN bkup=%u, id=%u, thmac=%llu, nonce=%u\n",
mp_opt->backup, mp_opt->join_id,
mp_opt->thmac, mp_opt->nonce);
} else if (opsize == TCPOLEN_MPTCP_MPJ_ACK) {
mp_opt->suboptions |= OPTION_MPTCP_MPJ_ACK;
ptr += 2;
memcpy(mp_opt->hmac, ptr, MPTCPOPT_HMAC_LEN);
pr_debug("MP_JOIN hmac");
pr_debug("MP_JOIN hmac\n");
}
break;

case MPTCPOPT_DSS:
pr_debug("DSS");
pr_debug("DSS\n");
ptr++;

/* we must clear 'mpc_map' be able to detect MP_CAPABLE
Expand All @@ -169,7 +169,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
mp_opt->ack64 = (flags & MPTCP_DSS_ACK64) != 0;
mp_opt->use_ack = (flags & MPTCP_DSS_HAS_ACK);

pr_debug("data_fin=%d dsn64=%d use_map=%d ack64=%d use_ack=%d",
pr_debug("data_fin=%d dsn64=%d use_map=%d ack64=%d use_ack=%d\n",
mp_opt->data_fin, mp_opt->dsn64,
mp_opt->use_map, mp_opt->ack64,
mp_opt->use_ack);
Expand Down Expand Up @@ -207,7 +207,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
ptr += 4;
}

pr_debug("data_ack=%llu", mp_opt->data_ack);
pr_debug("data_ack=%llu\n", mp_opt->data_ack);
}

if (mp_opt->use_map) {
Expand All @@ -231,7 +231,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
ptr += 2;
}

pr_debug("data_seq=%llu subflow_seq=%u data_len=%u csum=%d:%u",
pr_debug("data_seq=%llu subflow_seq=%u data_len=%u csum=%d:%u\n",
mp_opt->data_seq, mp_opt->subflow_seq,
mp_opt->data_len, !!(mp_opt->suboptions & OPTION_MPTCP_CSUMREQD),
mp_opt->csum);
Expand Down Expand Up @@ -293,7 +293,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
mp_opt->ahmac = get_unaligned_be64(ptr);
ptr += 8;
}
pr_debug("ADD_ADDR%s: id=%d, ahmac=%llu, echo=%d, port=%d",
pr_debug("ADD_ADDR%s: id=%d, ahmac=%llu, echo=%d, port=%d\n",
(mp_opt->addr.family == AF_INET6) ? "6" : "",
mp_opt->addr.id, mp_opt->ahmac, mp_opt->echo, ntohs(mp_opt->addr.port));
break;
Expand All @@ -309,7 +309,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
mp_opt->rm_list.nr = opsize - TCPOLEN_MPTCP_RM_ADDR_BASE;
for (i = 0; i < mp_opt->rm_list.nr; i++)
mp_opt->rm_list.ids[i] = *ptr++;
pr_debug("RM_ADDR: rm_list_nr=%d", mp_opt->rm_list.nr);
pr_debug("RM_ADDR: rm_list_nr=%d\n", mp_opt->rm_list.nr);
break;

case MPTCPOPT_MP_PRIO:
Expand All @@ -318,7 +318,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,

mp_opt->suboptions |= OPTION_MPTCP_PRIO;
mp_opt->backup = *ptr++ & MPTCP_PRIO_BKUP;
pr_debug("MP_PRIO: prio=%d", mp_opt->backup);
pr_debug("MP_PRIO: prio=%d\n", mp_opt->backup);
break;

case MPTCPOPT_MP_FASTCLOSE:
Expand All @@ -329,7 +329,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
mp_opt->rcvr_key = get_unaligned_be64(ptr);
ptr += 8;
mp_opt->suboptions |= OPTION_MPTCP_FASTCLOSE;
pr_debug("MP_FASTCLOSE: recv_key=%llu", mp_opt->rcvr_key);
pr_debug("MP_FASTCLOSE: recv_key=%llu\n", mp_opt->rcvr_key);
break;

case MPTCPOPT_RST:
Expand All @@ -343,7 +343,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
flags = *ptr++;
mp_opt->reset_transient = flags & MPTCP_RST_TRANSIENT;
mp_opt->reset_reason = *ptr;
pr_debug("MP_RST: transient=%u reason=%u",
pr_debug("MP_RST: transient=%u reason=%u\n",
mp_opt->reset_transient, mp_opt->reset_reason);
break;

Expand All @@ -354,7 +354,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
ptr += 2;
mp_opt->suboptions |= OPTION_MPTCP_FAIL;
mp_opt->fail_seq = get_unaligned_be64(ptr);
pr_debug("MP_FAIL: data_seq=%llu", mp_opt->fail_seq);
pr_debug("MP_FAIL: data_seq=%llu\n", mp_opt->fail_seq);
break;

default:
Expand Down Expand Up @@ -417,7 +417,7 @@ bool mptcp_syn_options(struct sock *sk, const struct sk_buff *skb,
*size = TCPOLEN_MPTCP_MPC_SYN;
return true;
} else if (subflow->request_join) {
pr_debug("remote_token=%u, nonce=%u", subflow->remote_token,
pr_debug("remote_token=%u, nonce=%u\n", subflow->remote_token,
subflow->local_nonce);
opts->suboptions = OPTION_MPTCP_MPJ_SYN;
opts->join_id = subflow->local_id;
Expand Down Expand Up @@ -500,7 +500,7 @@ static bool mptcp_established_options_mp(struct sock *sk, struct sk_buff *skb,
*size = TCPOLEN_MPTCP_MPC_ACK;
}

pr_debug("subflow=%p, local_key=%llu, remote_key=%llu map_len=%d",
pr_debug("subflow=%p, local_key=%llu, remote_key=%llu map_len=%d\n",
subflow, subflow->local_key, subflow->remote_key,
data_len);

Expand All @@ -509,7 +509,7 @@ static bool mptcp_established_options_mp(struct sock *sk, struct sk_buff *skb,
opts->suboptions = OPTION_MPTCP_MPJ_ACK;
memcpy(opts->hmac, subflow->hmac, MPTCPOPT_HMAC_LEN);
*size = TCPOLEN_MPTCP_MPJ_ACK;
pr_debug("subflow=%p", subflow);
pr_debug("subflow=%p\n", subflow);

/* we can use the full delegate action helper only from BH context
* If we are in process context - sk is flushing the backlog at
Expand Down Expand Up @@ -675,7 +675,7 @@ static bool mptcp_established_options_add_addr(struct sock *sk, struct sk_buff *

*size = len;
if (drop_other_suboptions) {
pr_debug("drop other suboptions");
pr_debug("drop other suboptions\n");
opts->suboptions = 0;

/* note that e.g. DSS could have written into the memory
Expand All @@ -695,7 +695,7 @@ static bool mptcp_established_options_add_addr(struct sock *sk, struct sk_buff *
} else {
MPTCP_INC_STATS(sock_net(sk), MPTCP_MIB_ECHOADDTX);
}
pr_debug("addr_id=%d, ahmac=%llu, echo=%d, port=%d",
pr_debug("addr_id=%d, ahmac=%llu, echo=%d, port=%d\n",
opts->addr.id, opts->ahmac, echo, ntohs(opts->addr.port));

return true;
Expand Down Expand Up @@ -726,7 +726,7 @@ static bool mptcp_established_options_rm_addr(struct sock *sk,
opts->rm_list = rm_list;

for (i = 0; i < opts->rm_list.nr; i++)
pr_debug("rm_list_ids[%d]=%d", i, opts->rm_list.ids[i]);
pr_debug("rm_list_ids[%d]=%d\n", i, opts->rm_list.ids[i]);
MPTCP_ADD_STATS(sock_net(sk), MPTCP_MIB_RMADDRTX, opts->rm_list.nr);
return true;
}
Expand All @@ -752,7 +752,7 @@ static bool mptcp_established_options_mp_prio(struct sock *sk,
opts->suboptions |= OPTION_MPTCP_PRIO;
opts->backup = subflow->request_bkup;

pr_debug("prio=%d", opts->backup);
pr_debug("prio=%d\n", opts->backup);

return true;
}
Expand Down Expand Up @@ -794,7 +794,7 @@ static bool mptcp_established_options_fastclose(struct sock *sk,
opts->suboptions |= OPTION_MPTCP_FASTCLOSE;
opts->rcvr_key = READ_ONCE(msk->remote_key);

pr_debug("FASTCLOSE key=%llu", opts->rcvr_key);
pr_debug("FASTCLOSE key=%llu\n", opts->rcvr_key);
MPTCP_INC_STATS(sock_net(sk), MPTCP_MIB_MPFASTCLOSETX);
return true;
}
Expand All @@ -816,7 +816,7 @@ static bool mptcp_established_options_mp_fail(struct sock *sk,
opts->suboptions |= OPTION_MPTCP_FAIL;
opts->fail_seq = subflow->map_seq;

pr_debug("MP_FAIL fail_seq=%llu", opts->fail_seq);
pr_debug("MP_FAIL fail_seq=%llu\n", opts->fail_seq);
MPTCP_INC_STATS(sock_net(sk), MPTCP_MIB_MPFAILTX);

return true;
Expand Down Expand Up @@ -904,7 +904,7 @@ bool mptcp_synack_options(const struct request_sock *req, unsigned int *size,
opts->csum_reqd = subflow_req->csum_reqd;
opts->allow_join_id0 = subflow_req->allow_join_id0;
*size = TCPOLEN_MPTCP_MPC_SYNACK;
pr_debug("subflow_req=%p, local_key=%llu",
pr_debug("subflow_req=%p, local_key=%llu\n",
subflow_req, subflow_req->local_key);
return true;
} else if (subflow_req->mp_join) {
Expand All @@ -913,7 +913,7 @@ bool mptcp_synack_options(const struct request_sock *req, unsigned int *size,
opts->join_id = subflow_req->local_id;
opts->thmac = subflow_req->thmac;
opts->nonce = subflow_req->local_nonce;
pr_debug("req=%p, bkup=%u, id=%u, thmac=%llu, nonce=%u",
pr_debug("req=%p, bkup=%u, id=%u, thmac=%llu, nonce=%u\n",
subflow_req, opts->backup, opts->join_id,
opts->thmac, opts->nonce);
*size = TCPOLEN_MPTCP_MPJ_SYNACK;
Expand Down
28 changes: 14 additions & 14 deletions net/mptcp/pm.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ int mptcp_pm_announce_addr(struct mptcp_sock *msk,
{
u8 add_addr = READ_ONCE(msk->pm.addr_signal);

pr_debug("msk=%p, local_id=%d, echo=%d", msk, addr->id, echo);
pr_debug("msk=%p, local_id=%d, echo=%d\n", msk, addr->id, echo);

lockdep_assert_held(&msk->pm.lock);

Expand All @@ -45,7 +45,7 @@ int mptcp_pm_remove_addr(struct mptcp_sock *msk, const struct mptcp_rm_list *rm_
{
u8 rm_addr = READ_ONCE(msk->pm.addr_signal);

pr_debug("msk=%p, rm_list_nr=%d", msk, rm_list->nr);
pr_debug("msk=%p, rm_list_nr=%d\n", msk, rm_list->nr);

if (rm_addr) {
MPTCP_ADD_STATS(sock_net((struct sock *)msk),
Expand All @@ -66,7 +66,7 @@ void mptcp_pm_new_connection(struct mptcp_sock *msk, const struct sock *ssk, int
{
struct mptcp_pm_data *pm = &msk->pm;

pr_debug("msk=%p, token=%u side=%d", msk, READ_ONCE(msk->token), server_side);
pr_debug("msk=%p, token=%u side=%d\n", msk, READ_ONCE(msk->token), server_side);

WRITE_ONCE(pm->server_side, server_side);
mptcp_event(MPTCP_EVENT_CREATED, msk, ssk, GFP_ATOMIC);
Expand All @@ -90,7 +90,7 @@ bool mptcp_pm_allow_new_subflow(struct mptcp_sock *msk)

subflows_max = mptcp_pm_get_subflows_max(msk);

pr_debug("msk=%p subflows=%d max=%d allow=%d", msk, pm->subflows,
pr_debug("msk=%p subflows=%d max=%d allow=%d\n", msk, pm->subflows,
subflows_max, READ_ONCE(pm->accept_subflow));

/* try to avoid acquiring the lock below */
Expand All @@ -114,7 +114,7 @@ bool mptcp_pm_allow_new_subflow(struct mptcp_sock *msk)
static bool mptcp_pm_schedule_work(struct mptcp_sock *msk,
enum mptcp_pm_status new_status)
{
pr_debug("msk=%p status=%x new=%lx", msk, msk->pm.status,
pr_debug("msk=%p status=%x new=%lx\n", msk, msk->pm.status,
BIT(new_status));
if (msk->pm.status & BIT(new_status))
return false;
Expand All @@ -129,7 +129,7 @@ void mptcp_pm_fully_established(struct mptcp_sock *msk, const struct sock *ssk)
struct mptcp_pm_data *pm = &msk->pm;
bool announce = false;

pr_debug("msk=%p", msk);
pr_debug("msk=%p\n", msk);

spin_lock_bh(&pm->lock);

Expand All @@ -153,14 +153,14 @@ void mptcp_pm_fully_established(struct mptcp_sock *msk, const struct sock *ssk)

void mptcp_pm_connection_closed(struct mptcp_sock *msk)
{
pr_debug("msk=%p", msk);
pr_debug("msk=%p\n", msk);
}

void mptcp_pm_subflow_established(struct mptcp_sock *msk)
{
struct mptcp_pm_data *pm = &msk->pm;

pr_debug("msk=%p", msk);
pr_debug("msk=%p\n", msk);

if (!READ_ONCE(pm->work_pending))
return;
Expand Down Expand Up @@ -212,7 +212,7 @@ void mptcp_pm_add_addr_received(const struct sock *ssk,
struct mptcp_sock *msk = mptcp_sk(subflow->conn);
struct mptcp_pm_data *pm = &msk->pm;

pr_debug("msk=%p remote_id=%d accept=%d", msk, addr->id,
pr_debug("msk=%p remote_id=%d accept=%d\n", msk, addr->id,
READ_ONCE(pm->accept_addr));

mptcp_event_addr_announced(ssk, addr);
Expand Down Expand Up @@ -243,7 +243,7 @@ void mptcp_pm_add_addr_echoed(struct mptcp_sock *msk,
{
struct mptcp_pm_data *pm = &msk->pm;

pr_debug("msk=%p", msk);
pr_debug("msk=%p\n", msk);

spin_lock_bh(&pm->lock);

Expand All @@ -267,7 +267,7 @@ void mptcp_pm_rm_addr_received(struct mptcp_sock *msk,
struct mptcp_pm_data *pm = &msk->pm;
u8 i;

pr_debug("msk=%p remote_ids_nr=%d", msk, rm_list->nr);
pr_debug("msk=%p remote_ids_nr=%d\n", msk, rm_list->nr);

for (i = 0; i < rm_list->nr; i++)
mptcp_event_addr_removed(msk, rm_list->ids[i]);
Expand Down Expand Up @@ -299,19 +299,19 @@ void mptcp_pm_mp_fail_received(struct sock *sk, u64 fail_seq)
struct mptcp_subflow_context *subflow = mptcp_subflow_ctx(sk);
struct mptcp_sock *msk = mptcp_sk(subflow->conn);

pr_debug("fail_seq=%llu", fail_seq);
pr_debug("fail_seq=%llu\n", fail_seq);

if (!READ_ONCE(msk->allow_infinite_fallback))
return;

if (!subflow->fail_tout) {
pr_debug("send MP_FAIL response and infinite map");
pr_debug("send MP_FAIL response and infinite map\n");

subflow->send_mp_fail = 1;
subflow->send_infinite_map = 1;
tcp_send_ack(sk);
} else {
pr_debug("MP_FAIL response received");
pr_debug("MP_FAIL response received\n");
WRITE_ONCE(subflow->fail_tout, 0);
}
}
Expand Down
Loading

0 comments on commit 2fe0d6d

Please sign in to comment.