search

multipath-tcp / mptcp

⚠️⚠️⚠️ Deprecated 🚫 Out-of-tree Linux Kernel implementation of MultiPath TCP. 👉 Use https://github.com/multipath-tcp/mptcp_net-next repo instead ⚠️⚠️⚠️
https://github.com/multipath-tcp/mptcp_net-next
Other
890 stars 335 forks source link

MPTCP: 0.94 mptcp_init4_subsockets mptcp_add_sock failed #245

Closed D4rk4 closed 5 years ago

D4rk4 commented 6 years ago

Strange errors in syslog:

[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0
[Sun Mar 11 16:34:35 2018] mptcp_init4_subsockets mptcp_add_sock failed ret: 0

Kernel: 4.14.24.mptcp Config:

kernel.osrelease = 4.14.24.mptcp
net.mptcp.mptcp_checksum = 0
net.mptcp.mptcp_debug = 0
net.mptcp.mptcp_enabled = 1
net.mptcp.mptcp_path_manager = fullmesh
net.mptcp.mptcp_scheduler = default
net.mptcp.mptcp_syn_retries = 15
net.mptcp.mptcp_version = 0
echo 3 > /sys/module/mptcp_fullmesh/parameters/num_subflows
echo 1 > /sys/module/mptcp_fullmesh/parameters/create_on_err
D4rk4 commented 6 years ago

Same errors on another 2 linux boxes with kernel 4.14.24.mptcp

cpaasch commented 6 years ago

You are trying to create too many subflows. We currently only support up to 32 subflows per MPTCP connection.

With your num_subflows configuration of 3, you will create 3 subflows per source/destination IP address pair. How many IPs do you have on the client and server?

D4rk4 commented 6 years ago

On client 2 IPs (interfaces), on server only one.

cpaasch commented 6 years ago

That's surprising. I would have expected more interfaces.

Can you show the output of ip addr show?

Also, can you enable mptcp-debugging with sysctl -w net.mptcp.mptcp_debug=1 and then create some MPTCP connections and show us the output of dmesg.

Thanks!

D4rk4 commented 6 years ago 
root@gw-gorica:~# ip addr show
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
2: enp1s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq master br0 state UP group default qlen 1000
    link/ether 00:0d:b9:49:79:24 brd ff:ff:ff:ff:ff:ff
3: enp2s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq master br0 state UP group default qlen 1000
    link/ether 00:0d:b9:49:79:25 brd ff:ff:ff:ff:ff:ff
4: enp3s0: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc fq master br0 state DOWN group default qlen 1000
    link/ether 00:0d:b9:49:79:26 brd ff:ff:ff:ff:ff:ff
5: enp8s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq state UP group default qlen 1000
    link/ether d8:9d:b9:00:33:a5 brd ff:ff:ff:ff:ff:ff
    inet 10.1.1.8/24 brd 10.1.1.255 scope global enp8s0
       valid_lft forever preferred_lft forever
6: enp9s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq state UP group default qlen 1000
    link/ether d8:9d:b9:00:33:a6 brd ff:ff:ff:ff:ff:ff
    inet 10.1.2.100/24 brd 10.1.2.255 scope global enp9s0
       valid_lft forever preferred_lft forever
7: wlp4s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue master br0 state UP group default qlen 1000
    link/ether 6c:3b:6b:f1:a0:11 brd ff:ff:ff:ff:ff:ff
8: br0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
    link/ether 00:0d:b9:49:79:24 brd ff:ff:ff:ff:ff:ff
    inet 10.0.5.1/24 brd 10.0.5.255 scope global br0
       valid_lft forever preferred_lft forever
9: tun0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc htb state UNKNOWN group default qlen 2048
    link/none
    inet 172.30.22.2/29 brd 172.30.22.7 scope global tun0
       valid_lft forever preferred_lft forever
10: tun0-ifb: <BROADCAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc htb state UNKNOWN group default qlen 32
    link/ether a2:2d:68:a1:ad:1b brd ff:ff:ff:ff:ff:ff

[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xe94c716c pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38863, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x507f4d96 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:13633, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xcfc385a0 pi 3, src_addr:172.30.22.2:22 dst_addr:10.0.5.174:14371, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x230c49ad pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:45333, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x54f30335 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x2da81b36 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xb606af37 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x3af66339 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x86540739 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xb411573b pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x844a133e pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x670e1740 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x332f4345 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xa739d391 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x74d1391 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xb13f1794 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x236da397 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x5c704f98 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xd612979a pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x7fa7f9b pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xf94f439c pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xf16a5ba0 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x98ce1fa0 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xd9e8d3a3 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xcce7f3a5 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x79215bac pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x113a27ac pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x13f4dbb6 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x99908bb7 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x809f5bb7 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x80b7d3bd pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x5b81da05 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:35479, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x24a3cbfe pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:35935, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xa91e57bd pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x2741a1a pi 3, src_addr:10.0.5.1:3126 dst_addr:10.0.5.174:6959, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xea1437bd pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xfcf33fbf pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x56a91bc1 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x188137c2 pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0x25aa63c5 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x82ea0622 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:2643, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x82f24645 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:52545, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xabb4de4c pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:47303, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x9f54e57 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:4815, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x11163687 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:15933, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x5df36ebe pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38943, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xdf823331 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38445, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xb28ef737 pi 3, src_addr:10.0.5.1:3126 dst_addr:10.0.5.174:12873, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x8d7f4f47 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:60703, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x777e475f pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:61499, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xdb5e9763 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:17545, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x86782f6a pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:49987, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0x199c7b6c pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:63977, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xc340d3c8 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:30187, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_add_sock: token 0xda4bebe7 pi 3, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:30901, cnt_subflows now 2
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:28 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:29 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:30 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:19 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:20 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:21 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:10 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:11 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:12 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:4 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:5 state 7 is_meta? 0
[Mon Mar 12 20:15:11 2018] mptcp_del_sock: Removing subsock tok 0xc5b47dd pi:6 state 7 is_meta? 0
[Mon Mar 12 20:15:19 2018] mptcp_sock_destruct destroying meta-sk token 0x31396f6c
[Mon Mar 12 20:15:29 2018] INFO: rcu_sched detected stalls on CPUs/tasks:
[Mon Mar 12 20:15:29 2018]  0-...: (1 GPs behind) idle=dca/140000000000000/0 softirq=12418472/12418473 fqs=2621 
[Mon Mar 12 20:15:29 2018]  (detected by 1, t=5252 jiffies, g=6375804, c=6375803, q=16389)
[Mon Mar 12 20:15:29 2018] Sending NMI from CPU 1 to CPUs 0:
[Mon Mar 12 20:15:29 2018] NMI backtrace for cpu 0
[Mon Mar 12 20:15:29 2018] CPU: 0 PID: 13963 Comm: kworker/u4:5 Tainted: P           O    4.14.24.mptcp #9
[Mon Mar 12 20:15:29 2018] Hardware name: PC Engines APU/APU, BIOS 4.0 09/08/2014
[Mon Mar 12 20:15:29 2018] Workqueue: mptcp_wq mptcp_sub_close_wq
[Mon Mar 12 20:15:29 2018] task: ffff8800b8fcadc0 task.stack: ffffc9000b040000
[Mon Mar 12 20:15:29 2018] RIP: 0010:io_serial_in+0x14/0x20
[Mon Mar 12 20:15:29 2018] RSP: 0018:ffffc9000b043c08 EFLAGS: 00000002
[Mon Mar 12 20:15:29 2018] RAX: 0000594545138400 RBX: ffffffff825cbe40 RCX: 0000000000000000
[Mon Mar 12 20:15:29 2018] RDX: 00000000000003fd RSI: 0000000000000005 RDI: ffffffff825cbe40
[Mon Mar 12 20:15:29 2018] RBP: 00000000000026f5 R08: 0000000000000000 R09: 0000000000000005
[Mon Mar 12 20:15:29 2018] R10: 0000000000000007 R11: ffffffff82583fcd R12: 0000000000000020
[Mon Mar 12 20:15:29 2018] R13: ffffffff82584017 R14: 0000000000000057 R15: 0000000000000046
[Mon Mar 12 20:15:29 2018] FS:  0000000000000000(0000) GS:ffff88011ec00000(0000) knlGS:0000000000000000
[Mon Mar 12 20:15:29 2018] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[Mon Mar 12 20:15:29 2018] CR2: 00007f9b3ce7f260 CR3: 000000010be0c000 CR4: 00000000000006f0
[Mon Mar 12 20:15:29 2018] Call Trace:
[Mon Mar 12 20:15:29 2018]  wait_for_xmitr+0x3a/0xa0
[Mon Mar 12 20:15:29 2018]  serial8250_console_putchar+0x16/0x30
[Mon Mar 12 20:15:29 2018]  ? wait_for_xmitr+0xa0/0xa0
[Mon Mar 12 20:15:29 2018]  uart_console_write+0x2b/0x60
[Mon Mar 12 20:15:29 2018]  serial8250_console_write+0xd9/0x280
[Mon Mar 12 20:15:29 2018]  ? print_prefix+0xbf/0x1b0
[Mon Mar 12 20:15:29 2018]  ? msg_print_text+0xa1/0x110
[Mon Mar 12 20:15:29 2018]  console_unlock+0x3ea/0x4d0
[Mon Mar 12 20:15:29 2018]  vprintk_emit+0x2fc/0x3a0
[Mon Mar 12 20:15:29 2018]  ? __clear_rsb+0x25/0x3d
[Mon Mar 12 20:15:29 2018]  printk+0x43/0x4b
[Mon Mar 12 20:15:29 2018]  ? __clear_rsb+0x15/0x3d
[Mon Mar 12 20:15:29 2018]  mptcp_del_sock.part.18+0x22d/0x260
[Mon Mar 12 20:15:29 2018]  tcp_v4_destroy_sock+0x235/0x270
[Mon Mar 12 20:15:29 2018]  inet_csk_destroy_sock+0x47/0x100
[Mon Mar 12 20:15:29 2018]  tcp_close+0x220/0x460
[Mon Mar 12 20:15:29 2018]  mptcp_sub_close_wq+0x50/0xd0
[Mon Mar 12 20:15:29 2018]  process_one_work+0x172/0x360
[Mon Mar 12 20:15:29 2018]  worker_thread+0x4d/0x3c0
[Mon Mar 12 20:15:29 2018]  kthread+0xfc/0x130
[Mon Mar 12 20:15:29 2018]  ? process_one_work+0x360/0x360
[Mon Mar 12 20:15:29 2018]  ? kthread_create_on_node+0x40/0x40
[Mon Mar 12 20:15:29 2018]  ret_from_fork+0x22/0x40
[Mon Mar 12 20:15:29 2018] Code: 00 00 00 d3 e6 48 63 f6 48 03 77 10 8b 06 c3 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 0f b6 8f a1 00 00 00 8b 57 08 d3 e6 01 f2 ec <0f> b6 c0 c3 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 0f b6 8f a1 
[Mon Mar 12 20:15:32 2018] mptcp_sock_destruct destroying meta-sk token 0xdfd9786c
[Mon Mar 12 20:15:32 2018] INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 0-... } 5357 jiffies s: 1633 root: 0x1/.
[Mon Mar 12 20:15:32 2018] blocking rcu_node structures:
[Mon Mar 12 20:15:32 2018] Task dump for CPU 0:
[Mon Mar 12 20:15:32 2018] kworker/u4:5    R  running task        0 13963      2 0x80000008
[Mon Mar 12 20:15:32 2018] Workqueue: mptcp_wq mptcp_sub_close_wq
[Mon Mar 12 20:15:32 2018] Call Trace:
[Mon Mar 12 20:15:32 2018]  ? do_softirq.part.17+0x3d/0x50
[Mon Mar 12 20:15:32 2018]  ? __local_bh_enable_ip+0x55/0x60
[Mon Mar 12 20:15:32 2018]  ? tcp_close+0x173/0x460
[Mon Mar 12 20:15:32 2018]  ? mptcp_sub_close_wq+0x50/0xd0
[Mon Mar 12 20:15:32 2018]  ? process_one_work+0x172/0x360
[Mon Mar 12 20:15:32 2018]  ? worker_thread+0x4d/0x3c0
[Mon Mar 12 20:15:32 2018]  ? kthread+0xfc/0x130
[Mon Mar 12 20:15:32 2018]  ? process_one_work+0x360/0x360
[Mon Mar 12 20:15:32 2018]  ? kthread_create_on_node+0x40/0x40
[Mon Mar 12 20:15:32 2018]  ? ret_from_fork+0x22/0x40
[Mon Mar 12 20:15:38 2018] mptcp_close: Close of meta_sk with tok 0x5b81da05
[Mon Mar 12 20:15:48 2018] mptcp_del_sock: Removing subsock tok 0x507f4d96 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:48 2018] mptcp_del_sock: Removing subsock tok 0x507f4d96 pi:3 state 7 is_meta? 0
[Mon Mar 12 20:15:49 2018] mptcp_add_sock: token 0xe2fe28dc pi 4, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:15961, cnt_subflows now 3
[Mon Mar 12 20:15:49 2018] mptcp_del_sock: Removing subsock tok 0xe2fe28dc pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:49 2018] mptcp_add_sock: token 0xe2fe28dc pi 5, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:24439, cnt_subflows now 3
[Mon Mar 12 20:15:49 2018] mptcp_alloc_mpcb: created mpcb with token 0x1eb7b19e
[Mon Mar 12 20:15:49 2018] mptcp_add_sock: token 0x1eb7b19e pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38196, cnt_subflows now 1
[Mon Mar 12 20:15:49 2018] mptcp_alloc_mpcb: created mpcb with token 0x1affade2
[Mon Mar 12 20:15:49 2018] mptcp_add_sock: token 0x1affade2 pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38198, cnt_subflows now 1
[Mon Mar 12 20:15:49 2018] mptcp_alloc_mpcb: created mpcb with token 0x7b363b95
[Mon Mar 12 20:15:49 2018] mptcp_add_sock: token 0x7b363b95 pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38200, cnt_subflows now 1
[Mon Mar 12 20:15:50 2018] mptcp_alloc_mpcb: created mpcb with token 0xe6ebb431
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0xe6ebb431 pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38202, cnt_subflows now 1
[Mon Mar 12 20:15:50 2018] mptcp_alloc_mpcb: created mpcb with token 0x9962b7b4
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0x9962b7b4 pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:38204, cnt_subflows now 1
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0x1eb7b19e pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:11889, cnt_subflows now 2
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0x1affade2 pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:27485, cnt_subflows now 2
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0x7b363b95 pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:32015, cnt_subflows now 2
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0xe6ebb431 pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:26429, cnt_subflows now 2
[Mon Mar 12 20:15:50 2018] mptcp_add_sock: token 0x9962b7b4 pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:16155, cnt_subflows now 2
[Mon Mar 12 20:15:51 2018] mptcp_del_sock: Removing subsock tok 0xb28ef737 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:51 2018] mptcp_alloc_mpcb: created mpcb with token 0xaa9d691c
[Mon Mar 12 20:15:51 2018] mptcp_add_sock: token 0xaa9d691c pi 1, src_addr:10.0.5.1:22 dst_addr:10.0.5.174:37844, cnt_subflows now 1
[Mon Mar 12 20:15:51 2018] mptcp_add_sock: token 0xaa9d691c pi 2, src_addr:172.30.22.2:22 dst_addr:10.0.5.174:52103, cnt_subflows now 2
[Mon Mar 12 20:15:52 2018] mptcp_del_sock: Removing subsock tok 0x5b81da05 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:52 2018] mptcp_del_sock: Removing subsock tok 0xcfc385a0 pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:53 2018] mptcp_alloc_mpcb: created mpcb with token 0x4e1ef50e
[Mon Mar 12 20:15:53 2018] mptcp_add_sock: token 0x4e1ef50e pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:43818, cnt_subflows now 1
[Mon Mar 12 20:15:53 2018] mptcp_alloc_mpcb: created mpcb with token 0x3208d2c3
[Mon Mar 12 20:15:53 2018] mptcp_add_sock: token 0x3208d2c3 pi 1, src_addr:10.0.5.1:3126 dst_addr:10.0.5.174:36424, cnt_subflows now 1
[Mon Mar 12 20:15:54 2018] mptcp_add_sock: token 0x4e1ef50e pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:8411, cnt_subflows now 2
[Mon Mar 12 20:15:54 2018] mptcp_add_sock: token 0x3208d2c3 pi 2, src_addr:10.0.5.1:3126 dst_addr:10.0.5.174:3745, cnt_subflows now 2
[Mon Mar 12 20:15:54 2018] mptcp_close: Close of meta_sk with tok 0x507f4d96
[Mon Mar 12 20:15:54 2018] mptcp_close: Close of meta_sk with tok 0x4e1ef50e
[Mon Mar 12 20:15:54 2018] mptcp_del_sock: Removing subsock tok 0x4e1ef50e pi:2 state 7 is_meta? 0
[Mon Mar 12 20:15:54 2018] mptcp_del_sock: Removing subsock tok 0x4e1ef50e pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:54 2018] mptcp_del_sock: Removing subsock tok 0xcfc385a0 pi:3 state 7 is_meta? 0
[Mon Mar 12 20:15:54 2018] mptcp_alloc_mpcb: created mpcb with token 0x957d37c4
[Mon Mar 12 20:15:54 2018] mptcp_add_sock: token 0x957d37c4 pi 1, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:51768, cnt_subflows now 1
[Mon Mar 12 20:15:54 2018] mptcp_add_sock: token 0x957d37c4 pi 2, src_addr:10.0.5.1:3127 dst_addr:10.0.5.174:4545, cnt_subflows now 2
[Mon Mar 12 20:15:54 2018] mptcp_sock_destruct destroying meta-sk token 0x4e1ef50e
[Mon Mar 12 20:15:55 2018] mptcp_alloc_mpcb: created mpcb with token 0x7ba3c632
[Mon Mar 12 20:15:55 2018] mptcp_add_sock: token 0x7ba3c632 pi 1, src_addr:10.0.5.1:3126 dst_addr:10.0.5.174:36428, cnt_subflows now 1
[Mon Mar 12 20:15:55 2018] mptcp_add_sock: token 0x7ba3c632 pi 2, src_addr:10.0.5.1:3126 dst_addr:10.0.5.174:45739, cnt_subflows now 2
[Mon Mar 12 20:15:56 2018] mptcp_del_sock: Removing subsock tok 0x9bb4483f pi:1 state 7 is_meta? 0
[Mon Mar 12 20:15:56 2018] mptcp_del_sock: Removing subsock tok 0x9bb4483f pi:3 state 7 is_meta? 0
kpeletidis commented 6 years ago

I saw the 'mptcp_init4_subsockets mptcp_add_sock failed' messages with mptcp 0.94 as well, on the Sender's side, as soon as the transfer started.

I had set up fou tunnels and the IP addresses of both the tunnel and the physical interfaces were in /proc/net/mptcp_fullmesh.

When I disabled mptcp on the physical interfaces (e.g. ip link set dev eth0 multipath off) the messages stopped. I hope this helps a bit.

cpaasch commented 6 years ago

@D4rk4 - in the dmesg output you posted, there is no message about a failed mptcp_add_sock. It also looks like your machine is getting slowed down by the printing of the debug-messages. Are you creating a lot of connections on this machine?

Can you turn off the mptcp_debug sysctl again and apply the below debug-patch? That should give a better hint as to what is failing:

commit 60f7c5e6667a68005a4eb1c124dc3a4b44b83b83
Author: Christoph Paasch <cpaasch@apple.com>
Date:   Sun Mar 11 19:02:25 2018 -0700

    mptcp: Improved debugging

    Allow to print the value of ret when mptcp_add_sock fails.

    Signed-off-by: Christoph Paasch <cpaasch@apple.com>

diff --git a/net/mptcp/mptcp_ipv4.c b/net/mptcp/mptcp_ipv4.c
index 99ff09225ebf..36cdbf09a5b9 100644
--- a/net/mptcp/mptcp_ipv4.c
+++ b/net/mptcp/mptcp_ipv4.c
@@ -280,7 +280,8 @@ int mptcp_init4_subsockets(struct sock *meta_sk, const struct mptcp_loc4 *loc,
    lockdep_set_class_and_name(&(sk)->sk_lock.slock, &meta_slock_key, meta_slock_key_name);
    lockdep_init_map(&(sk)->sk_lock.dep_map, meta_key_name, &meta_key, 0);

-   if (mptcp_add_sock(meta_sk, sk, loc->loc4_id, rem->rem4_id, GFP_KERNEL)) {
+   ret = mptcp_add_sock(meta_sk, sk, loc->loc4_id, rem->rem4_id, GFP_KERNEL);
+   if (ret) {
        net_err_ratelimited("%s mptcp_add_sock failed ret: %d\n",
                    __func__, ret);
        goto error;
diff --git a/net/mptcp/mptcp_ipv6.c b/net/mptcp/mptcp_ipv6.c
index 04b69220baef..bde4a9d7ab32 100644
--- a/net/mptcp/mptcp_ipv6.c
+++ b/net/mptcp/mptcp_ipv6.c
@@ -306,7 +306,8 @@ int mptcp_init6_subsockets(struct sock *meta_sk, const struct mptcp_loc6 *loc,
    lockdep_set_class_and_name(&(sk)->sk_lock.slock, &meta_slock_key, meta_slock_key_name);
    lockdep_init_map(&(sk)->sk_lock.dep_map, meta_key_name, &meta_key, 0);

-   if (mptcp_add_sock(meta_sk, sk, loc->loc6_id, rem->rem6_id, GFP_KERNEL)) {
+   ret = mptcp_add_sock(meta_sk, sk, loc->loc6_id, rem->rem6_id, GFP_KERNEL);
+   if (ret) {
        net_err_ratelimited("%s mptcp_add_sock failed ret: %d\n",
                    __func__, ret);
        goto error;
cpaasch commented 5 years ago

Closing due to inactivity.