Closed rstanislav closed 3 years ago
matttbe
commented
3 years ago Hi,
Thank you for the bug report. Is it easy to reproduce?
I can understand the bug seems to be in MPTCP but we don't have the kernel v5.4.83 in our repo. I don't have a setup to reproduce or try to understand the issue.
Would it be possible to report this bug to openmptcprouter project instead?
matttbe
commented
3 years ago Or would it be possible to reproduce it with a v4.19 kernel you think?
matttbe
commented
3 years ago If it is easy to reproduce, please try this patch:
diff --git a/net/mptcp/mptcp_output.c b/net/mptcp/mptcp_output.c
index 326798f19f07..39eae2199802 100644
--- a/net/mptcp/mptcp_output.c
+++ b/net/mptcp/mptcp_output.c
@@ -1710,7 +1710,7 @@ int mptcp_retransmit_skb(struct sock *meta_sk, struct sk_buff *skb)
return 0;
failed:
- __NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPRETRANSFAIL);
+ NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPRETRANSFAIL);
return err;
}
rstanislav
commented
3 years ago Hello! Thanks for help! It's easy reproducable, i have applied patch above & recompilled kernel, same bug :(
[ 882.608295] BUG: using this_cpu_add() in preemptible [00000000] code: ss-redir/536 [ 882.608321] caller is mptcp_retransmit_skb+0x14c/0x2a0 [ 882.608334] CPU: 1 PID: 536 Comm: ss-redir Tainted: G C O 5.4.83-v8+ #1 [ 882.608338] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT) [ 882.608343] Call trace: [ 882.608351] dump_backtrace+0x0/0x158 [ 882.608357] show_stack+0x24/0x30 [ 882.608363] dump_stack+0xd8/0x150 [ 882.608373] __this_cpu_preempt_check+0x130/0x150 [ 882.608380] mptcp_retransmit_skb+0x14c/0x2a0 [ 882.608386] mptcp_write_xmit+0x3ec/0x460 [ 882.608395] tcp_push_pending_frames+0x60/0xe8 [ 882.608401] tcp_push+0x100/0x1a0 [ 882.608406] tcp_sendmsg_locked+0xaa8/0xd78 [ 882.608411] tcp_sendmsg+0x40/0x60 [ 882.608418] inet_sendmsg+0x4c/0x70 [ 882.608426] sock_sendmsg+0x54/0x60 [ 882.608432] sys_sendto+0x11c/0x148 [ 882.608439] __arm64_sys_sendto+0x30/0x40 [ 882.608448] el0_svc_common.constprop.1+0x7c/0x1a8 [ 882.608455] el0_svc_handler+0x34/0xa0 [ 882.608461] el0_svc+0x8/0x204 [ 1409.485291] BUG: using this_cpu_add() in preemptible [00000000] code: ss-redir/536 [ 1409.485318] caller is mptcp_retransmit_skb+0x14c/0x2a0 [ 1409.485330] CPU: 2 PID: 536 Comm: ss-redir Tainted: G C O 5.4.83-v8+ #1 [ 1409.485335] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT) [ 1409.485339] Call trace: [ 1409.485348] dump_backtrace+0x0/0x158 [ 1409.485354] show_stack+0x24/0x30 [ 1409.485361] dump_stack+0xd8/0x150 [ 1409.485371] __this_cpu_preempt_check+0x130/0x150 [ 1409.485378] mptcp_retransmit_skb+0x14c/0x2a0 [ 1409.485384] mptcp_write_xmit+0x3ec/0x460 [ 1409.485393] tcp_push_pending_frames+0x60/0xe8 [ 1409.485400] mptcp_send_fin+0x114/0x170 [ 1409.485406] mptcp_close+0x5c0/0x650 [ 1409.485411] tcp_close+0x53c/0x558 [ 1409.485418] inet_release+0x48/0x70 [ 1409.485426] sock_release+0x4c/0xd0 [ 1409.485432] sock_close+0x24/0x38 [ 1409.485440] fput+0x94/0x238 [ 1409.485445] __fput+0x20/0x30 [ 1409.485452] task_work_run+0x88/0x138 [ 1409.485457] do_notify_resume+0x12c/0x678 [ 1409.485463] work_pending+0x8/0x14
I have 2 devices for tests, is there anything i can do to trace issue ?
matttbe
commented
3 years ago I'm a bit blind with the code and I don't know what has been modified in the openmptcprouter project. Could they have a look? Maybe they had conflicts around that and know where to limit the area to search?
I have 2 devices for tests, is there anything i can do to trace issue ?
It could be very interesting to know what are the possible paths to go from mptcp_retransmit_skb() to __this_cpu_preempt_check(). And trace which one was used here.
I'm not sure if this would help:
echo show_stack > /sys/kernel/tracing/set_graph_function
echo printk > /sys/kernel/tracing/set_graph_notrace
echo function_graph > /sys/kernel/tracing/current_tracer
# <reproduce>
cat /sys/kernel/tracing/trace # but if you have a BUG(), you will not be able to do this step :)Did more tests and found that kernel was not updated, after update with patch above there is no more messages from mptcp_retransmit_skb, now found 1 new -
[ 2802.063494] BUG: using this_cpu_add() in preemptible [00000000] code: ss-redir/493 [ 2802.063526] caller is mptcp_process_data_ack+0x67c/0xb18 [ 2802.063541] CPU: 3 PID: 493 Comm: ss-redir Tainted: G C O 5.4.83-v8+ #2 [ 2802.063548] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT) [ 2802.063553] Call trace: [ 2802.063564] dump_backtrace+0x0/0x158 [ 2802.063572] show_stack+0x24/0x30 [ 2802.063581] dump_stack+0xd8/0x150 [ 2802.063593] this_cpu_preempt_check+0x130/0x150 [ 2802.063602] mptcp_process_data_ack+0x67c/0xb18 [ 2802.063611] mptcp_handle_options+0x1b0/0x5d0 [ 2802.063622] tcp_validate_incoming+0x40c/0x540 [ 2802.063630] tcp_rcv_state_process+0xe4/0xcf0 [ 2802.063637] tcp_v4_do_rcv+0x1ec/0x2c8 [ 2802.063645] mptcp_backlog_rcv+0xa4/0xd8 [ 2802.063655] __release_sock+0x78/0xc0 [ 2802.063662] release_sock+0x34/0x90 [ 2802.063670] mptcp_close+0x214/0x650 [ 2802.063677] tcp_close+0x53c/0x558 [ 2802.063685] inet_release+0x48/0x70 [ 2802.063694] sock_release+0x4c/0xd0 [ 2802.063702] sock_close+0x24/0x38 [ 2802.063712] fput+0x94/0x238 [ 2802.063719] ____fput+0x20/0x30 [ 2802.063729] task_work_run+0x88/0x138 [ 2802.063735] do_notify_resume+0x12c/0x678 [ 2802.063743] work_pending+0x8/0x14
But its rare, only 1 in about 4 hours
matttbe
commented
3 years ago Thanks for the new tests!
I quickly looked and I think a few other modifications seem to be needed:
May you try this please?
diff --git a/net/mptcp/mptcp_ctrl.c b/net/mptcp/mptcp_ctrl.c
index 3f254f4a9f9e..f17e8de3e20d 100644
--- a/net/mptcp/mptcp_ctrl.c
+++ b/net/mptcp/mptcp_ctrl.c
@@ -2785,7 +2785,7 @@ int mptcp_conn_request(struct sock *sk, struct sk_buff *skb)
#endif
}
drop:
- __NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENDROPS);
+ NET_INC_STATS(sock_net(sk), LINUX_MIB_LISTENDROPS);
return 0;
}
diff --git a/net/mptcp/mptcp_input.c b/net/mptcp/mptcp_input.c
index b04a4c97bb31..46e48a56be48 100644
--- a/net/mptcp/mptcp_input.c
+++ b/net/mptcp/mptcp_input.c
@@ -221,7 +221,7 @@ static int mptcp_rcv_state_process(struct sock *meta_sk, struct sock *sk,
meta_tp->rcv_nxt))) {
mptcp_send_active_reset(meta_sk, GFP_ATOMIC);
tcp_done(meta_sk);
- __NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPABORTONDATA);
+ NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPABORTONDATA);
return -1;
}
@@ -262,7 +262,7 @@ static int mptcp_rcv_state_process(struct sock *meta_sk, struct sock *sk,
if (TCP_SKB_CB(skb)->end_seq != TCP_SKB_CB(skb)->seq &&
after(TCP_SKB_CB(skb)->end_seq - th->fin, tp->rcv_nxt) &&
!mptcp_is_data_fin2(skb, tp)) {
- __NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPABORTONDATA);
+ NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPABORTONDATA);
mptcp_send_active_reset(meta_sk, GFP_ATOMIC);
tcp_reset(meta_sk);
return -1;
diff --git a/net/mptcp/mptcp_output.c b/net/mptcp/mptcp_output.c
index 326798f19f07..39eae2199802 100644
--- a/net/mptcp/mptcp_output.c
+++ b/net/mptcp/mptcp_output.c
@@ -1710,7 +1710,7 @@ int mptcp_retransmit_skb(struct sock *meta_sk, struct sk_buff *skb)
return 0;
failed:
- __NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPRETRANSFAIL);
+ NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPRETRANSFAIL);
return err;
}
@@ -1769,7 +1769,7 @@ void mptcp_meta_retransmit_timer(struct sock *meta_sk)
return;
if (meta_icsk->icsk_retransmits == 0)
- __NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPTIMEOUTS);
+ NET_INC_STATS(sock_net(meta_sk), LINUX_MIB_TCPTIMEOUTS);
meta_icsk->icsk_ca_state = TCP_CA_Loss;
Recompilled kernel and tested for about 2 days under load - no more messages in dmesg and no more lags(i thinks its somehow caused load peaks and subflow's disconnections), thanks alot for help & patch!
matttbe
commented
3 years ago Thank you for having validated the patch.
I'm going to re-open this ticket: I need to apply this patch in the repo. I would like to validate it myself but not sure it will be possible soon. Will see!
System is Raspberry pi 4B, raspbian 64 bit kernel v5.4.83 with last mptcp version (patch from openmptcprouter project) , under load dmesg have every few seconds this message: (is this case program was ss-redir, but there is few other cases with openvpn and other network applications, bug message is always the same (looks like some error in mptcp_retransmit_skb? )