net/dccp: warning in dccp_feat_clone_sp_val/__might_sleep

Hi,

I've got the following error report while running the syzkaller fuzzer:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 4608 at kernel/sched/core.c:7724
__might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
do not call blocking ops when !TASK_RUNNING; state=1 set at
[<ffffffff811f5a5c>] prepare_to_wait+0xbc/0x210
kernel/sched/wait.c:178
Modules linked in:
CPU: 0 PID: 4608 Comm: syz-executor Not tainted 4.9.0-rc2+ #320
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 ffff88006625f7a0 ffffffff81b46914 ffff88006625f818 0000000000000000
 ffffffff84052960 0000000000000000 ffff88006625f7e8 ffffffff81111237
 ffff88006aceac00 ffffffff00001e2c ffffed000cc4beff ffffffff84052960
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff81b46914>] dump_stack+0xb3/0x10f lib/dump_stack.c:51
 [<ffffffff81111237>] __warn+0x1a7/0x1f0 kernel/panic.c:550
 [<ffffffff8111132c>] warn_slowpath_fmt+0xac/0xd0 kernel/panic.c:565
 [<ffffffff811922fc>] __might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
 [<     inline     >] slab_pre_alloc_hook mm/slab.h:393
 [<     inline     >] slab_alloc_node mm/slub.c:2634
 [<     inline     >] slab_alloc mm/slub.c:2716
 [<ffffffff81508da0>] __kmalloc_track_caller+0x150/0x2a0 mm/slub.c:4240
 [<ffffffff8146be14>] kmemdup+0x24/0x50 mm/util.c:113
 [<ffffffff8388b2cf>] dccp_feat_clone_sp_val.part.5+0x4f/0xe0
net/dccp/feat.c:374
 [<     inline     >] dccp_feat_clone_sp_val net/dccp/feat.c:1141
 [<     inline     >] dccp_feat_change_recv net/dccp/feat.c:1141
 [<ffffffff8388d491>] dccp_feat_parse_options+0xaa1/0x13d0 net/dccp/feat.c:1411
 [<ffffffff83894f01>] dccp_parse_options+0x721/0x1010 net/dccp/options.c:128
 [<ffffffff83891280>] dccp_rcv_state_process+0x200/0x15b0 net/dccp/input.c:644
 [<ffffffff838b8a94>] dccp_v4_do_rcv+0xf4/0x1a0 net/dccp/ipv4.c:681
 [<     inline     >] sk_backlog_rcv ./include/net/sock.h:872
 [<ffffffff82b7ceb6>] __release_sock+0x126/0x3a0 net/core/sock.c:2044
 [<ffffffff82b7d189>] release_sock+0x59/0x1c0 net/core/sock.c:2502
 [<     inline     >] inet_wait_for_connect net/ipv4/af_inet.c:547
 [<ffffffff8316b2a2>] __inet_stream_connect+0x5d2/0xbb0 net/ipv4/af_inet.c:617
 [<ffffffff8316b8d5>] inet_stream_connect+0x55/0xa0 net/ipv4/af_inet.c:656
 [<ffffffff82b705e4>] SYSC_connect+0x244/0x2f0 net/socket.c:1533
 [<ffffffff82b72dd4>] SyS_connect+0x24/0x30 net/socket.c:1514
 [<ffffffff83fbf701>] entry_SYSCALL_64_fastpath+0x1f/0xc2
arch/x86/entry/entry_64.S:209
---[ end trace 0dc4109d69f4e51e ]---

On commit 14970f204b1993af7459d5bd34aaff38dfee6670 (Oct 27).

A reproducer is attached.

On Fri, Oct 28, 2016 at 5:40 PM, Andrey Konovalov [off-list ref] wrote:

Hi,

I've got the following error report while running the syzkaller fuzzer:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 4608 at kernel/sched/core.c:7724
__might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
do not call blocking ops when !TASK_RUNNING; state=1 set at
[<ffffffff811f5a5c>] prepare_to_wait+0xbc/0x210
kernel/sched/wait.c:178
Modules linked in:
CPU: 0 PID: 4608 Comm: syz-executor Not tainted 4.9.0-rc2+ #320
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 ffff88006625f7a0 ffffffff81b46914 ffff88006625f818 0000000000000000
 ffffffff84052960 0000000000000000 ffff88006625f7e8 ffffffff81111237
 ffff88006aceac00 ffffffff00001e2c ffffed000cc4beff ffffffff84052960
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff81b46914>] dump_stack+0xb3/0x10f lib/dump_stack.c:51
 [<ffffffff81111237>] __warn+0x1a7/0x1f0 kernel/panic.c:550
 [<ffffffff8111132c>] warn_slowpath_fmt+0xac/0xd0 kernel/panic.c:565
 [<ffffffff811922fc>] __might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
 [<     inline     >] slab_pre_alloc_hook mm/slab.h:393
 [<     inline     >] slab_alloc_node mm/slub.c:2634
 [<     inline     >] slab_alloc mm/slub.c:2716
 [<ffffffff81508da0>] __kmalloc_track_caller+0x150/0x2a0 mm/slub.c:4240
 [<ffffffff8146be14>] kmemdup+0x24/0x50 mm/util.c:113
 [<ffffffff8388b2cf>] dccp_feat_clone_sp_val.part.5+0x4f/0xe0
net/dccp/feat.c:374
 [<     inline     >] dccp_feat_clone_sp_val net/dccp/feat.c:1141
 [<     inline     >] dccp_feat_change_recv net/dccp/feat.c:1141
 [<ffffffff8388d491>] dccp_feat_parse_options+0xaa1/0x13d0 net/dccp/feat.c:1411
 [<ffffffff83894f01>] dccp_parse_options+0x721/0x1010 net/dccp/options.c:128
 [<ffffffff83891280>] dccp_rcv_state_process+0x200/0x15b0 net/dccp/input.c:644
 [<ffffffff838b8a94>] dccp_v4_do_rcv+0xf4/0x1a0 net/dccp/ipv4.c:681
 [<     inline     >] sk_backlog_rcv ./include/net/sock.h:872
 [<ffffffff82b7ceb6>] __release_sock+0x126/0x3a0 net/core/sock.c:2044
 [<ffffffff82b7d189>] release_sock+0x59/0x1c0 net/core/sock.c:2502
 [<     inline     >] inet_wait_for_connect net/ipv4/af_inet.c:547
 [<ffffffff8316b2a2>] __inet_stream_connect+0x5d2/0xbb0 net/ipv4/af_inet.c:617
 [<ffffffff8316b8d5>] inet_stream_connect+0x55/0xa0 net/ipv4/af_inet.c:656
 [<ffffffff82b705e4>] SYSC_connect+0x244/0x2f0 net/socket.c:1533
 [<ffffffff82b72dd4>] SyS_connect+0x24/0x30 net/socket.c:1514
 [<ffffffff83fbf701>] entry_SYSCALL_64_fastpath+0x1f/0xc2
arch/x86/entry/entry_64.S:209

Should be fixed the attached patch. I will verify it with your
reproducer tomorrow.

Thanks!

Hi Cong,

Tested with your patch, still getting a warning, though it's a little different:

------------[ cut here ]------------
WARNING: CPU: 1 PID: 3876 at kernel/sched/core.c:7724
__might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
do not call blocking ops when !TASK_RUNNING; state=1 set at
[<ffffffff811f5a5c>] prepare_to_wait+0xbc/0x210
kernel/sched/wait.c:178
Modules linked in:
CPU: 1 PID: 3876 Comm: a.out Not tainted 4.9.0-rc2+ #325
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 ffff88006c2d7770 ffffffff81b46914 ffff88006c2d77e8 0000000000000000
 ffffffff84052960 0000000000000000 ffff88006c2d77b8 ffffffff81111237
 0000000041b58ab3 ffffffff00001e2c ffffed000d85aef9 ffffffff84052960
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff81b46914>] dump_stack+0xb3/0x10f lib/dump_stack.c:51
 [<ffffffff81111237>] __warn+0x1a7/0x1f0 kernel/panic.c:550
 [<ffffffff8111132c>] warn_slowpath_fmt+0xac/0xd0 kernel/panic.c:565
 [<ffffffff811922fc>] __might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
 [<     inline     >] slab_pre_alloc_hook mm/slab.h:393
 [<     inline     >] slab_alloc_node mm/slub.c:2634
 [<     inline     >] slab_alloc mm/slub.c:2716
 [<ffffffff815054fb>] kmem_cache_alloc_trace+0x1bb/0x270 mm/slub.c:2733
 [<     inline     >] kmalloc ./include/linux/slab.h:490
 [<ffffffff83889e62>] dccp_feat_entry_new+0x182/0x2a0 net/dccp/feat.c:468
 [<ffffffff8388a1ea>] dccp_feat_push_confirm+0x3a/0x270 net/dccp/feat.c:516
 [<     inline     >] dccp_feat_change_recv net/dccp/feat.c:1160
 [<ffffffff8388d587>] dccp_feat_parse_options+0xb37/0x13d0 net/dccp/feat.c:1412
 [<ffffffff83894f61>] dccp_parse_options+0x721/0x1010 net/dccp/options.c:128
 [<ffffffff838912e0>] dccp_rcv_state_process+0x200/0x15b0 net/dccp/input.c:644
 [<ffffffff838b8af4>] dccp_v4_do_rcv+0xf4/0x1a0 net/dccp/ipv4.c:681
 [<     inline     >] sk_backlog_rcv ./include/net/sock.h:872
 [<ffffffff82b7ceb6>] __release_sock+0x126/0x3a0 net/core/sock.c:2044
 [<ffffffff82b7d189>] release_sock+0x59/0x1c0 net/core/sock.c:2502
 [<     inline     >] inet_wait_for_connect net/ipv4/af_inet.c:547
 [<ffffffff8316b2a2>] __inet_stream_connect+0x5d2/0xbb0 net/ipv4/af_inet.c:617
 [<ffffffff8316b8d5>] inet_stream_connect+0x55/0xa0 net/ipv4/af_inet.c:656
 [<ffffffff82b705e4>] SYSC_connect+0x244/0x2f0 net/socket.c:1533
 [<ffffffff82b72dd4>] SyS_connect+0x24/0x30 net/socket.c:1514
 [<ffffffff83fbf781>] entry_SYSCALL_64_fastpath+0x1f/0xc2
arch/x86/entry/entry_64.S:209
---[ end trace c7e036cf4dc54077 ]---

Thanks!

On Sat, Oct 29, 2016 at 8:10 AM, Cong Wang [off-list ref] wrote:

On Fri, Oct 28, 2016 at 5:40 PM, Andrey Konovalov [off-list ref] wrote:

quoted

Hi,

I've got the following error report while running the syzkaller fuzzer:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 4608 at kernel/sched/core.c:7724
__might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
do not call blocking ops when !TASK_RUNNING; state=1 set at
[<ffffffff811f5a5c>] prepare_to_wait+0xbc/0x210
kernel/sched/wait.c:178
Modules linked in:
CPU: 0 PID: 4608 Comm: syz-executor Not tainted 4.9.0-rc2+ #320
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 ffff88006625f7a0 ffffffff81b46914 ffff88006625f818 0000000000000000
 ffffffff84052960 0000000000000000 ffff88006625f7e8 ffffffff81111237
 ffff88006aceac00 ffffffff00001e2c ffffed000cc4beff ffffffff84052960
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff81b46914>] dump_stack+0xb3/0x10f lib/dump_stack.c:51
 [<ffffffff81111237>] __warn+0x1a7/0x1f0 kernel/panic.c:550
 [<ffffffff8111132c>] warn_slowpath_fmt+0xac/0xd0 kernel/panic.c:565
 [<ffffffff811922fc>] __might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
 [<     inline     >] slab_pre_alloc_hook mm/slab.h:393
 [<     inline     >] slab_alloc_node mm/slub.c:2634
 [<     inline     >] slab_alloc mm/slub.c:2716
 [<ffffffff81508da0>] __kmalloc_track_caller+0x150/0x2a0 mm/slub.c:4240
 [<ffffffff8146be14>] kmemdup+0x24/0x50 mm/util.c:113
 [<ffffffff8388b2cf>] dccp_feat_clone_sp_val.part.5+0x4f/0xe0
net/dccp/feat.c:374
 [<     inline     >] dccp_feat_clone_sp_val net/dccp/feat.c:1141
 [<     inline     >] dccp_feat_change_recv net/dccp/feat.c:1141
 [<ffffffff8388d491>] dccp_feat_parse_options+0xaa1/0x13d0 net/dccp/feat.c:1411
 [<ffffffff83894f01>] dccp_parse_options+0x721/0x1010 net/dccp/options.c:128
 [<ffffffff83891280>] dccp_rcv_state_process+0x200/0x15b0 net/dccp/input.c:644
 [<ffffffff838b8a94>] dccp_v4_do_rcv+0xf4/0x1a0 net/dccp/ipv4.c:681
 [<     inline     >] sk_backlog_rcv ./include/net/sock.h:872
 [<ffffffff82b7ceb6>] __release_sock+0x126/0x3a0 net/core/sock.c:2044
 [<ffffffff82b7d189>] release_sock+0x59/0x1c0 net/core/sock.c:2502
 [<     inline     >] inet_wait_for_connect net/ipv4/af_inet.c:547
 [<ffffffff8316b2a2>] __inet_stream_connect+0x5d2/0xbb0 net/ipv4/af_inet.c:617
 [<ffffffff8316b8d5>] inet_stream_connect+0x55/0xa0 net/ipv4/af_inet.c:656
 [<ffffffff82b705e4>] SYSC_connect+0x244/0x2f0 net/socket.c:1533
 [<ffffffff82b72dd4>] SyS_connect+0x24/0x30 net/socket.c:1514
 [<ffffffff83fbf701>] entry_SYSCALL_64_fastpath+0x1f/0xc2
arch/x86/entry/entry_64.S:209

Should be fixed the attached patch. I will verify it with your
reproducer tomorrow.

Thanks!

On Sat, 2016-10-29 at 19:06 +0200, Andrey Konovalov wrote:

Hi Cong,

Tested with your patch, still getting a warning, though it's a little different:

------------[ cut here ]------------
WARNING: CPU: 1 PID: 3876 at kernel/sched/core.c:7724
__might_sleep+0x14c/0x1a0 kernel/sched/core.c:7719
do not call blocking ops when !TASK_RUNNING; state=1 set at
[<ffffffff811f5a5c>] prepare_to_wait+0xbc/0x210
kernel/sched/wait.c:178
Modules linked in:

This looks like the following patch is needed, can you test it ?
Thanks !

diff --git a/net/dccp/output.c b/net/dccp/output.c
index b66c84db0766..74d8583a0d52 100644
--- a/net/dccp/output.c
+++ b/net/dccp/output.c

@@ -228,6 +228,7 @@ static int dccp_wait_for_ccid(struct sock *sk, unsigned long delay)
 
 	remaining = schedule_timeout(delay);
 
+	sched_annotate_sleep();
 	lock_sock(sk);
 	sk->sk_write_pending--;
 	finish_wait(sk_sleep(sk), &wait);

Hi Eric,

Tested with both patches applied, still seeing the warning.

Thanks!

On Sat, Oct 29, 2016 at 7:43 PM, Eric Dumazet [off-list ref] wrote:

On Sat, 2016-10-29 at 19:59 +0200, Andrey Konovalov wrote:

Hi Eric,

Tested with both patches applied, still seeing the warning.

Thanks!

Arg, sorry, this was at the wrong place.

Thanks for testing !

diff --git a/net/dccp/output.c b/net/dccp/output.c
index b66c84db0766..2548edff86ff 100644
--- a/net/dccp/output.c
+++ b/net/dccp/output.c

@@ -224,6 +224,11 @@ static int dccp_wait_for_ccid(struct sock *sk, unsigned long delay)
 
 	prepare_to_wait(sk_sleep(sk), &wait, TASK_INTERRUPTIBLE);
 	sk->sk_write_pending++;
+
+	/* release_sock()/lock_sock() will process socket backlog
+	 * from process context. Be prepared to sleep !
+	 */
+	sched_annotate_sleep();
 	release_sock(sk);
 
 	remaining = schedule_timeout(delay);

Sorry, the warning is still there.

I'm not sure adding sched_annotate_sleep() does anything, since it's
defined as (in case CONFIG_DEBUG_ATOMIC_SLEEP is not set):
# define sched_annotate_sleep() do { } while (0)

On Sat, Oct 29, 2016 at 8:05 PM, Eric Dumazet [off-list ref] wrote:

On Sun, 2016-10-30 at 05:41 +0100, Andrey Konovalov wrote:

Sorry, the warning is still there.

I'm not sure adding sched_annotate_sleep() does anything, since it's
defined as (in case CONFIG_DEBUG_ATOMIC_SLEEP is not set):
# define sched_annotate_sleep() do { } while (0)

Thanks again for testing.

But you do have CONFIG_DEBUG_ATOMIC_SLEEP set, which triggers a check in
__might_sleep() :

WARN_ONCE(current->state != TASK_RUNNING && current->task_state_change,

Relevant commit is 00845eb968ead28007338b2bb852b8beef816583
("sched: don't cause task state changes in nested sleep debugging")

Another relevant commit was 26cabd31259ba43f68026ce3f62b78094124333f
("sched, net: Clean up sk_wait_event() vs. might_sleep()") 

Before release_sock() could process the backlog in process context, only
lock_sock() could trigger the issue, so my fix at that time was commit
cb7cf8a33ff73cf638481d1edf883d8968f934f8 ("inet: Clean up
inet_csk_wait_for_connect() vs. might_sleep()")

I guess we need something else now, because the following :

static int dccp_wait_for_ccid(struct sock *sk, unsigned long delay)
{
        DEFINE_WAIT(wait);
        long remaining;

        prepare_to_wait(sk_sleep(sk), &wait, TASK_INTERRUPTIBLE);
        sk->sk_write_pending++;
        release_sock(sk);
	...


can now process the socket backlog in process context from
release_sock(), so all GFP_KERNEL allocations might barf because of
TASK_INTERRUPTIBLE being used at that point.

sk_wait_event() probably also needs a fix.

Peter, any idea how this can be done ?

Thanks !

On Sun, Oct 30, 2016 at 6:20 AM, Eric Dumazet [off-list ref] wrote:

On Sun, 2016-10-30 at 05:41 +0100, Andrey Konovalov wrote:

quoted

Sorry, the warning is still there.

I'm not sure adding sched_annotate_sleep() does anything, since it's
defined as (in case CONFIG_DEBUG_ATOMIC_SLEEP is not set):
# define sched_annotate_sleep() do { } while (0)

Thanks again for testing.

But you do have CONFIG_DEBUG_ATOMIC_SLEEP set, which triggers a check in
__might_sleep() :

WARN_ONCE(current->state != TASK_RUNNING && current->task_state_change,

Relevant commit is 00845eb968ead28007338b2bb852b8beef816583
("sched: don't cause task state changes in nested sleep debugging")

Another relevant commit was 26cabd31259ba43f68026ce3f62b78094124333f
("sched, net: Clean up sk_wait_event() vs. might_sleep()")

Before release_sock() could process the backlog in process context, only
lock_sock() could trigger the issue, so my fix at that time was commit
cb7cf8a33ff73cf638481d1edf883d8968f934f8 ("inet: Clean up
inet_csk_wait_for_connect() vs. might_sleep()")

Thanks for the context, but isn't the original warning reported by Andrey is
from inet_wait_for_connect()? You seem only patch some dccp function
which is why it is still there?

It should be the following, no?

diff --git a/net/ipv4/af_inet.c b/net/ipv4/af_inet.c
index 9648c97..bbd8159 100644
--- a/net/ipv4/af_inet.c
+++ b/net/ipv4/af_inet.c

@@ -544,6 +544,7 @@ static long inet_wait_for_connect(struct sock *sk,

long timeo, int writebias)
         * without closing the socket.
         */
        while ((1 << sk->sk_state) & (TCPF_SYN_SENT | TCPF_SYN_RECV)) {
+               sched_annotate_sleep();
                release_sock(sk);
                timeo = schedule_timeout(timeo);
                lock_sock(sk);

On Mon, 2016-10-31 at 11:00 -0700, Cong Wang wrote:

Yes, this would be one of the locations needing this.

Hi Cong,

Yes, your patches fix the warnings.

Tested-by: Andrey Konovalov <redacted>

Thanks!

On Mon, Oct 31, 2016 at 7:40 PM, Eric Dumazet [off-list ref] wrote:

On Mon, 2016-10-31 at 11:00 -0700, Cong Wang wrote:

quoted

On Sun, Oct 30, 2016 at 6:20 AM, Eric Dumazet [off-list ref] wrote:

quoted

On Sun, 2016-10-30 at 05:41 +0100, Andrey Konovalov wrote:

quoted

Sorry, the warning is still there.

I'm not sure adding sched_annotate_sleep() does anything, since it's
defined as (in case CONFIG_DEBUG_ATOMIC_SLEEP is not set):
# define sched_annotate_sleep() do { } while (0)

Thanks again for testing.

But you do have CONFIG_DEBUG_ATOMIC_SLEEP set, which triggers a check in
__might_sleep() :

WARN_ONCE(current->state != TASK_RUNNING && current->task_state_change,

Relevant commit is 00845eb968ead28007338b2bb852b8beef816583
("sched: don't cause task state changes in nested sleep debugging")

Another relevant commit was 26cabd31259ba43f68026ce3f62b78094124333f
("sched, net: Clean up sk_wait_event() vs. might_sleep()")

Before release_sock() could process the backlog in process context, only
lock_sock() could trigger the issue, so my fix at that time was commit
cb7cf8a33ff73cf638481d1edf883d8968f934f8 ("inet: Clean up
inet_csk_wait_for_connect() vs. might_sleep()")

Thanks for the context, but isn't the original warning reported by Andrey is
from inet_wait_for_connect()? You seem only patch some dccp function
which is why it is still there?

It should be the following, no?

diff --git a/net/ipv4/af_inet.c b/net/ipv4/af_inet.c
index 9648c97..bbd8159 100644
--- a/net/ipv4/af_inet.c
+++ b/net/ipv4/af_inet.c

@@ -544,6 +544,7 @@ static long inet_wait_for_connect(struct sock *sk,

long timeo, int writebias)
         * without closing the socket.
         */
        while ((1 << sk->sk_state) & (TCPF_SYN_SENT | TCPF_SYN_RECV)) {
+               sched_annotate_sleep();
                release_sock(sk);
                timeo = schedule_timeout(timeo);
                lock_sock(sk);

Yes, this would be one of the locations needing this.