Skip to content

Commit cb41b19

Browse files
matttbekuba-moo
matttbe
authored and
kuba-moo
committed
mptcp: pr_debug: add missing \n at the end
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 (...) 10.75 - end 15.76 - restart 013 signal address [ 10.367935] mptcp:mptcp_pm_add_addr_echoed: MPTCP: msk=(...) (...) => a delay of 5 seconds: printed with a 10.36 ts, but after 'restart' which was printed at the 15.76 ts. 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") Cc: stable@vger.kernel.org Reviewed-by: Geliang Tang <geliang@kernel.org> Signed-off-by: Matthieu Baerts (NGI0) <matttbe@kernel.org> Link: https://patch.msgid.link/20240826-net-mptcp-close-extra-sf-fin-v1-4-905199fe1172@kernel.org Signed-off-by: Jakub Kicinski <kuba@kernel.org>
1 parent 2a1f596 commit cb41b19

9 files changed

Lines changed: 107 additions & 107 deletions

File tree

‎net/mptcp/fastopen.c‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -68,12 +68,12 @@ void __mptcp_fastopen_gen_msk_ackseq(struct mptcp_sock *msk, struct mptcp_subflo
6868
skb = skb_peek_tail(&sk->sk_receive_queue);
6969
if (skb) {
7070
WARN_ON_ONCE(MPTCP_SKB_CB(skb)->end_seq);
71-
pr_debug("msk %p moving seq %llx -> %llx end_seq %llx -> %llx", sk,
71+
pr_debug("msk %p moving seq %llx -> %llx end_seq %llx -> %llx\n", sk,
7272
MPTCP_SKB_CB(skb)->map_seq, MPTCP_SKB_CB(skb)->map_seq + msk->ack_seq,
7373
MPTCP_SKB_CB(skb)->end_seq, MPTCP_SKB_CB(skb)->end_seq + msk->ack_seq);
7474
MPTCP_SKB_CB(skb)->map_seq += msk->ack_seq;
7575
MPTCP_SKB_CB(skb)->end_seq += msk->ack_seq;
7676
}
7777

78-
pr_debug("msk=%p ack_seq=%llx", msk, msk->ack_seq);
78+
pr_debug("msk=%p ack_seq=%llx\n", msk, msk->ack_seq);
7979
}

‎net/mptcp/options.c‎

Lines changed: 25 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -117,7 +117,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
117117
mp_opt->suboptions |= OPTION_MPTCP_CSUMREQD;
118118
ptr += 2;
119119
}
120-
pr_debug("MP_CAPABLE version=%x, flags=%x, optlen=%d sndr=%llu, rcvr=%llu len=%d csum=%u",
120+
pr_debug("MP_CAPABLE version=%x, flags=%x, optlen=%d sndr=%llu, rcvr=%llu len=%d csum=%u\n",
121121
version, flags, opsize, mp_opt->sndr_key,
122122
mp_opt->rcvr_key, mp_opt->data_len, mp_opt->csum);
123123
break;
@@ -131,7 +131,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
131131
ptr += 4;
132132
mp_opt->nonce = get_unaligned_be32(ptr);
133133
ptr += 4;
134-
pr_debug("MP_JOIN bkup=%u, id=%u, token=%u, nonce=%u",
134+
pr_debug("MP_JOIN bkup=%u, id=%u, token=%u, nonce=%u\n",
135135
mp_opt->backup, mp_opt->join_id,
136136
mp_opt->token, mp_opt->nonce);
137137
} else if (opsize == TCPOLEN_MPTCP_MPJ_SYNACK) {
@@ -142,19 +142,19 @@ static void mptcp_parse_option(const struct sk_buff *skb,
142142
ptr += 8;
143143
mp_opt->nonce = get_unaligned_be32(ptr);
144144
ptr += 4;
145-
pr_debug("MP_JOIN bkup=%u, id=%u, thmac=%llu, nonce=%u",
145+
pr_debug("MP_JOIN bkup=%u, id=%u, thmac=%llu, nonce=%u\n",
146146
mp_opt->backup, mp_opt->join_id,
147147
mp_opt->thmac, mp_opt->nonce);
148148
} else if (opsize == TCPOLEN_MPTCP_MPJ_ACK) {
149149
mp_opt->suboptions |= OPTION_MPTCP_MPJ_ACK;
150150
ptr += 2;
151151
memcpy(mp_opt->hmac, ptr, MPTCPOPT_HMAC_LEN);
152-
pr_debug("MP_JOIN hmac");
152+
pr_debug("MP_JOIN hmac\n");
153153
}
154154
break;
155155

156156
case MPTCPOPT_DSS:
157-
pr_debug("DSS");
157+
pr_debug("DSS\n");
158158
ptr++;
159159

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

172-
pr_debug("data_fin=%d dsn64=%d use_map=%d ack64=%d use_ack=%d",
172+
pr_debug("data_fin=%d dsn64=%d use_map=%d ack64=%d use_ack=%d\n",
173173
mp_opt->data_fin, mp_opt->dsn64,
174174
mp_opt->use_map, mp_opt->ack64,
175175
mp_opt->use_ack);
@@ -207,7 +207,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
207207
ptr += 4;
208208
}
209209

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

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

234-
pr_debug("data_seq=%llu subflow_seq=%u data_len=%u csum=%d:%u",
234+
pr_debug("data_seq=%llu subflow_seq=%u data_len=%u csum=%d:%u\n",
235235
mp_opt->data_seq, mp_opt->subflow_seq,
236236
mp_opt->data_len, !!(mp_opt->suboptions & OPTION_MPTCP_CSUMREQD),
237237
mp_opt->csum);
@@ -293,7 +293,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
293293
mp_opt->ahmac = get_unaligned_be64(ptr);
294294
ptr += 8;
295295
}
296-
pr_debug("ADD_ADDR%s: id=%d, ahmac=%llu, echo=%d, port=%d",
296+
pr_debug("ADD_ADDR%s: id=%d, ahmac=%llu, echo=%d, port=%d\n",
297297
(mp_opt->addr.family == AF_INET6) ? "6" : "",
298298
mp_opt->addr.id, mp_opt->ahmac, mp_opt->echo, ntohs(mp_opt->addr.port));
299299
break;
@@ -309,7 +309,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
309309
mp_opt->rm_list.nr = opsize - TCPOLEN_MPTCP_RM_ADDR_BASE;
310310
for (i = 0; i < mp_opt->rm_list.nr; i++)
311311
mp_opt->rm_list.ids[i] = *ptr++;
312-
pr_debug("RM_ADDR: rm_list_nr=%d", mp_opt->rm_list.nr);
312+
pr_debug("RM_ADDR: rm_list_nr=%d\n", mp_opt->rm_list.nr);
313313
break;
314314

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

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

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

335335
case MPTCPOPT_RST:
@@ -343,7 +343,7 @@ static void mptcp_parse_option(const struct sk_buff *skb,
343343
flags = *ptr++;
344344
mp_opt->reset_transient = flags & MPTCP_RST_TRANSIENT;
345345
mp_opt->reset_reason = *ptr;
346-
pr_debug("MP_RST: transient=%u reason=%u",
346+
pr_debug("MP_RST: transient=%u reason=%u\n",
347347
mp_opt->reset_transient, mp_opt->reset_reason);
348348
break;
349349

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

360360
default:
@@ -417,7 +417,7 @@ bool mptcp_syn_options(struct sock *sk, const struct sk_buff *skb,
417417
*size = TCPOLEN_MPTCP_MPC_SYN;
418418
return true;
419419
} else if (subflow->request_join) {
420-
pr_debug("remote_token=%u, nonce=%u", subflow->remote_token,
420+
pr_debug("remote_token=%u, nonce=%u\n", subflow->remote_token,
421421
subflow->local_nonce);
422422
opts->suboptions = OPTION_MPTCP_MPJ_SYN;
423423
opts->join_id = subflow->local_id;
@@ -500,7 +500,7 @@ static bool mptcp_established_options_mp(struct sock *sk, struct sk_buff *skb,
500500
*size = TCPOLEN_MPTCP_MPC_ACK;
501501
}
502502

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

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

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

676676
*size = len;
677677
if (drop_other_suboptions) {
678-
pr_debug("drop other suboptions");
678+
pr_debug("drop other suboptions\n");
679679
opts->suboptions = 0;
680680

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

701701
return true;
@@ -726,7 +726,7 @@ static bool mptcp_established_options_rm_addr(struct sock *sk,
726726
opts->rm_list = rm_list;
727727

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

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

757757
return true;
758758
}
@@ -794,7 +794,7 @@ static bool mptcp_established_options_fastclose(struct sock *sk,
794794
opts->suboptions |= OPTION_MPTCP_FASTCLOSE;
795795
opts->rcvr_key = READ_ONCE(msk->remote_key);
796796

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

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

822822
return true;
@@ -904,7 +904,7 @@ bool mptcp_synack_options(const struct request_sock *req, unsigned int *size,
904904
opts->csum_reqd = subflow_req->csum_reqd;
905905
opts->allow_join_id0 = subflow_req->allow_join_id0;
906906
*size = TCPOLEN_MPTCP_MPC_SYNACK;
907-
pr_debug("subflow_req=%p, local_key=%llu",
907+
pr_debug("subflow_req=%p, local_key=%llu\n",
908908
subflow_req, subflow_req->local_key);
909909
return true;
910910
} else if (subflow_req->mp_join) {
@@ -913,7 +913,7 @@ bool mptcp_synack_options(const struct request_sock *req, unsigned int *size,
913913
opts->join_id = subflow_req->local_id;
914914
opts->thmac = subflow_req->thmac;
915915
opts->nonce = subflow_req->local_nonce;
916-
pr_debug("req=%p, bkup=%u, id=%u, thmac=%llu, nonce=%u",
916+
pr_debug("req=%p, bkup=%u, id=%u, thmac=%llu, nonce=%u\n",
917917
subflow_req, opts->backup, opts->join_id,
918918
opts->thmac, opts->nonce);
919919
*size = TCPOLEN_MPTCP_MPJ_SYNACK;

‎net/mptcp/pm.c‎

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@ int mptcp_pm_announce_addr(struct mptcp_sock *msk,
1919
{
2020
u8 add_addr = READ_ONCE(msk->pm.addr_signal);
2121

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

2424
lockdep_assert_held(&msk->pm.lock);
2525

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

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

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

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

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

9191
subflows_max = mptcp_pm_get_subflows_max(msk);
9292

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

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

132-
pr_debug("msk=%p", msk);
132+
pr_debug("msk=%p\n", msk);
133133

134134
spin_lock_bh(&pm->lock);
135135

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

154154
void mptcp_pm_connection_closed(struct mptcp_sock *msk)
155155
{
156-
pr_debug("msk=%p", msk);
156+
pr_debug("msk=%p\n", msk);
157157
}
158158

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

163-
pr_debug("msk=%p", msk);
163+
pr_debug("msk=%p\n", msk);
164164

165165
if (!READ_ONCE(pm->work_pending))
166166
return;
@@ -212,7 +212,7 @@ void mptcp_pm_add_addr_received(const struct sock *ssk,
212212
struct mptcp_sock *msk = mptcp_sk(subflow->conn);
213213
struct mptcp_pm_data *pm = &msk->pm;
214214

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

218218
mptcp_event_addr_announced(ssk, addr);
@@ -243,7 +243,7 @@ void mptcp_pm_add_addr_echoed(struct mptcp_sock *msk,
243243
{
244244
struct mptcp_pm_data *pm = &msk->pm;
245245

246-
pr_debug("msk=%p", msk);
246+
pr_debug("msk=%p\n", msk);
247247

248248
spin_lock_bh(&pm->lock);
249249

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

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

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

302-
pr_debug("fail_seq=%llu", fail_seq);
302+
pr_debug("fail_seq=%llu\n", fail_seq);
303303

304304
if (!READ_ONCE(msk->allow_infinite_fallback))
305305
return;
306306

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

310310
subflow->send_mp_fail = 1;
311311
subflow->send_infinite_map = 1;
312312
tcp_send_ack(sk);
313313
} else {
314-
pr_debug("MP_FAIL response received");
314+
pr_debug("MP_FAIL response received\n");
315315
WRITE_ONCE(subflow->fail_tout, 0);
316316
}
317317
}

0 commit comments

Comments
 (0)