use-after-free in sctp_do_sm

[Dmitry Vyukov]

Hello,

The following program triggers use-after-free in sctp_do_sm:

// autogenerated by syzkaller (http://github.com/google/syzkaller)
#include <syscall.h>
#include <string.h>
#include <stdint.h>

int main()
{
long r0 = syscall(SYS_socket, 0xaul, 0x80805ul, 0x0ul, 0, 0, 0);
long r1 = syscall(SYS_mmap, 0x20000000ul, 0x10000ul, 0x3ul,
0x32ul, 0xfffffffffffffffful, 0x0ul);
memcpy((void*)0x20002fe4,
"\x0a\x00\x33\xe7\xeb\x9d\xcf\x61\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\xc5\xc8\x88\x64",
28);
long r3 = syscall(SYS_bind, r0, 0x20002fe4ul, 0x1cul, 0, 0, 0);
memcpy((void*)0x20000faa,
"\x9b\x01\x7d\xcd\xb8\x6a\xc7\x3d\x09\x3a\x07\x00\xa7\xc4\xe9\xee\x0a\xd6\xec\xde\x26\x75\x5f\x22\xae\x4e\x33\x00\xb0\x76\x10\x70\xd6\xca\x19\xbc\x15\x83\xcf\x2e\xbc\x99\x0c\x5e\x83\x89\xc1\x44\x9c\x6e\x74\xd8\x5d\x5d\xd0\xf0\xdf\x47\xc0\x00\x71\x0b\x55\x4c\xab\xf0\xd8\x90\xd5\x92\x8c\x6e\x33\x22\x15\x5b\x19\xfb\xed\xdd\xa6\xac\xcb\x60\xcf\xe2\xde\xed\xdb\x95\x5c\xaa\x20\xa3",
94);
memcpy((void*)0x2000033a,
"\x02\x00\x33\xe2\x7f\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00",
128);
long r6 = syscall(SYS_sendto, r0, 0x20000faaul, 0x5eul,
0x81ul, 0x2000033aul, 0x80ul);
return 0;
}


==================================================================
BUG: KASAN: use-after-free in sctp_do_sm+0x42f6/0x4f60 at addr ffff880036fa80a8
Read of size 4 by task a.out/5664
=============================================================================
BUG kmalloc-4096 (Tainted: G B ): kasan: bad access detected
-----------------------------------------------------------------------------

INFO: Allocated in sctp_association_new+0x6f/0x1ea0 age=8 cpu=1 pid=5664
[< none >] kmem_cache_alloc_trace+0x1cf/0x220 ./mm/slab.c:3707
[< none >] sctp_association_new+0x6f/0x1ea0
[< none >] sctp_sendmsg+0x1954/0x28e0
[< none >] inet_sendmsg+0x316/0x4f0 ./net/ipv4/af_inet.c:802
[< inline >] __sock_sendmsg_nosec ./net/socket.c:641
[< inline >] __sock_sendmsg ./net/socket.c:651
[< none >] sock_sendmsg+0xca/0x110 ./net/socket.c:662
[< none >] SYSC_sendto+0x208/0x350 ./net/socket.c:1841
[< none >] SyS_sendto+0x40/0x50 ./net/socket.c:1862
[< none >] entry_SYSCALL_64_fastpath+0x16/0x7a

INFO: Freed in sctp_association_put+0x150/0x250 age=14 cpu=1 pid=5664
[< none >] kfree+0x199/0x1b0 ./mm/slab.c:1211
[< none >] sctp_association_put+0x150/0x250
[< none >] sctp_association_free+0x498/0x630
[< none >] sctp_do_sm+0xd8b/0x4f60
[< none >] sctp_primitive_SHUTDOWN+0xa9/0xd0
[< none >] sctp_close+0x616/0x790
[< none >] inet_release+0xed/0x1c0 ./net/ipv4/af_inet.c:471
[< none >] inet6_release+0x50/0x70 ./net/ipv6/af_inet6.c:416
[< inline >] constant_test_bit ././arch/x86/include/asm/bitops.h:321
[< none >] sock_release+0x8d/0x200 ./net/socket.c:601
[< none >] sock_close+0x16/0x20 ./net/socket.c:1188
[< none >] __fput+0x21d/0x6e0 ./fs/file_table.c:265
[< none >] ____fput+0x15/0x20 ./fs/file_table.c:84
[< none >] task_work_run+0x163/0x1f0 ./include/trace/events/rcu.h:20
[< inline >] __list_add ./include/linux/list.h:42
[< inline >] list_add_tail ./include/linux/list.h:76
[< inline >] list_move_tail ./include/linux/list.h:168
[< inline >] reparent_leader ./kernel/exit.c:618
[< inline >] forget_original_parent ./kernel/exit.c:669
[< inline >] exit_notify ./kernel/exit.c:697
[< none >] do_exit+0x809/0x2b90 ./kernel/exit.c:878
[< none >] do_group_exit+0x108/0x320 ./kernel/exit.c:985

INFO: Slab 0xffffea0000dbea00 objects=7 used=1 fp=0xffff880036fa8000
flags=0x100000000004080
INFO: Object 0xffff880036fa8000 @offset=0 fp=0xffff880036fad668
CPU: 1 PID: 5664 Comm: a.out Tainted: G B 4.4.0-rc1+ #81
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
00000000ffffffff ffff880061d6f700 ffffffff825d3336 ffff88003e806d00
ffff880036fa8000 ffff880036fa8000 ffff880061d6f730 ffffffff81618784
ffff88003e806d00 ffffea0000dbea00 ffff880036fa8000 0000000000000000

Call Trace:
[<ffffffff8162131e>] __asan_report_load4_noabort+0x3e/0x40
[<ffffffff8475ac76>] sctp_do_sm+0x42f6/0x4f60
[<ffffffff847b50e9>] sctp_primitive_SHUTDOWN+0xa9/0xd0
[<ffffffff847a1426>] sctp_close+0x616/0x790
[<ffffffff8409bb0d>] inet_release+0xed/0x1c0 ./net/ipv4/af_inet.c:471
[<ffffffff84192cc0>] inet6_release+0x50/0x70 ./net/ipv6/af_inet6.c:416
[< inline >] constant_test_bit ././arch/x86/include/asm/bitops.h:321
[<ffffffff83dc78cd>] sock_release+0x8d/0x200 ./net/socket.c:601
[<ffffffff83dc7a56>] sock_close+0x16/0x20 ./net/socket.c:1188
[<ffffffff81662f5d>] __fput+0x21d/0x6e0 ./fs/file_table.c:265
[<ffffffff816634a5>] ____fput+0x15/0x20 ./fs/file_table.c:84
[<ffffffff812a33d3>] task_work_run+0x163/0x1f0 ./include/trace/events/rcu.h:20
[< inline >] __list_add ./include/linux/list.h:42
[< inline >] list_add_tail ./include/linux/list.h:76
[< inline >] list_move_tail ./include/linux/list.h:168
[< inline >] reparent_leader ./kernel/exit.c:618
[< inline >] forget_original_parent ./kernel/exit.c:669
[< inline >] exit_notify ./kernel/exit.c:697
[<ffffffff812505d9>] do_exit+0x809/0x2b90 ./kernel/exit.c:878
[<ffffffff81252ad8>] do_group_exit+0x108/0x320 ./kernel/exit.c:985
[<ffffffff81252d0d>] SyS_exit_group+0x1d/0x20 ./kernel/exit.c:1002
[<ffffffff84bf0c36>] entry_SYSCALL_64_fastpath+0x16/0x7a
==================================================================


I am on commit 90b55590c43258a157a2a143748455dcc50fbb53 of net-next (Nov 22).


Thanks

[Dmitry Vyukov]

strace output for your convenience:

socket(PF_INET6, SOCK_SEQPACKET|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 3
mmap(0x20000000, 65536, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x20000000
bind(3, {sa_family=AF_INET6, sin6_port=htons(13287),
inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=1640996331,
sin6_scope_id=1686685893}, 28) = 0
sendto(3, "\233\1}\315\270j\307=\t:\7\0\247\304\351\356\n\326\354\336&u_\"\256N3\0\260v\20p"...,
94, MSG_OOB|MSG_EOR, {sa_family=AF_INET, sin_port=htons(13282),
sin_addr=inet_addr("127.0.0.1")}, 128) = 94
exit_group(0) = ?

[Dmitry Vyukov]

The right commit is:

commit 7d267278a9ece963d77eefec61630223fce08c6c
Author: Rainer Weikusat
Date: Fri Nov 20 22:07:23 2015 +0000
unix: avoid use-after-free in ep_remove_wait_queue

[Neil Horman]

This commit doesn't seem to exist

Neil

> --
> To unsubscribe from this list: send the line "unsubscribe linux-sctp" in
> the body of a message to majo...@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>

[Eric Dumazet]

It does, in David Miller net tree :

commit 7d267278a9ece963d77eefec61630223fce08c6c
Author: Rainer Weikusat <rwei...@mobileactivedefense.com>

[David Miller]

From: Neil Horman <nho...@tuxdriver.com>
Date: Tue, 24 Nov 2015 15:45:54 -0500

>> The right commit is:
>>
>> commit 7d267278a9ece963d77eefec61630223fce08c6c
>> Author: Rainer Weikusat
>> Date: Fri Nov 20 22:07:23 2015 +0000
>> unix: avoid use-after-free in ep_remove_wait_queue
> This commit doesn't seem to exist

It's in the 'net' tree. Which hasn't been pulled into 'net-next' for
a few days.

[Vlad Yasevich]

I don't think this matters... I think what's happening is that a close is happening on a
socket still in connection initialization phase and we've never handled that particularly
well...

Net-next kernel with mem debugging hangs on boot for me with a ton of printks suppressed.
Will try the net kernel to see if that's better

-vlad

[Dmitry Vyukov]

This also seems to lead the the following WARNINGS:

------------[ cut here ]------------
WARNING: CPU: 3 PID: 21734 at kernel/jump_label.c:77
__static_key_slow_dec+0xfb/0x120()
jump label: negative count!
Modules linked in:
CPU: 3 PID: 21734 Comm: executor Tainted: G B W 4.4.0-rc2+ #3

Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011

00000000ffffffff ffff88006083f660 ffffffff82719fc6 ffff88006083f6d0
ffff88003bbf8000 ffffffff85a612e0 ffff88006083f6a0 ffffffff81244ec9
ffffffff8152c54b ffffed000c107ed6 ffffffff85a612e0 000000000000004d
Call Trace:
[< inline >] __dump_stack lib/dump_stack.c:15
[<ffffffff82719fc6>] dump_stack+0x68/0x92 lib/dump_stack.c:50
[<ffffffff81244ec9>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:460
[<ffffffff81244fd9>] warn_slowpath_fmt+0xa9/0xd0 kernel/panic.c:472
[<ffffffff8152c54b>] __static_key_slow_dec+0xfb/0x120 kernel/jump_label.c:76
[<ffffffff8152c5c1>] static_key_slow_dec+0x51/0x90 kernel/jump_label.c:100
[<ffffffff84962d9b>] net_disable_timestamp+0x3b/0x50 net/core/dev.c:1709
[<ffffffff84914d43>] sock_disable_timestamp+0x93/0xb0 net/core/sock.c:444
[<ffffffff8491f82c>] sk_destruct+0xec/0x440 net/core/sock.c:1457
[<ffffffff8491fbd7>] __sk_free+0x57/0x200 net/core/sock.c:1476
[<ffffffff8491fdb0>] sk_free+0x30/0x40 net/core/sock.c:1487
[< inline >] sock_put include/net/sock.h:1623
[<ffffffff854c8a18>] sctp_close+0x628/0x790 net/sctp/socket.c:1546
[<ffffffff84d4b3ed>] inet_release+0xed/0x1c0 net/ipv4/af_inet.c:413
[<ffffffff84e70240>] inet6_release+0x50/0x70 net/ipv6/af_inet6.c:406
[<ffffffff84909bbd>] sock_release+0x8d/0x1d0 net/socket.c:571
[<ffffffff84909d16>] sock_close+0x16/0x20 net/socket.c:1022
[<ffffffff81663a00>] __fput+0x220/0x770 fs/file_table.c:208
[<ffffffff81663fd5>] ____fput+0x15/0x20 fs/file_table.c:244
[<ffffffff8129f673>] task_work_run+0x163/0x1f0 kernel/task_work.c:115
[< inline >] exit_task_work include/linux/task_work.h:21
[<ffffffff8124d9e9>] do_exit+0x809/0x2ae0 kernel/exit.c:750
[<ffffffff8124fe38>] do_group_exit+0x108/0x320 kernel/exit.c:880
[<ffffffff81271df7>] get_signal+0x597/0x1630 kernel/signal.c:2307
[<ffffffff8114c77f>] do_signal+0x7f/0x18e0 arch/x86/kernel/signal.c:709
[<ffffffff81003901>] exit_to_usermode_loop+0xf1/0x1a0
arch/x86/entry/common.c:247
[< inline >] prepare_exit_to_usermode arch/x86/entry/common.c:282
[<ffffffff8100616f>] syscall_return_slowpath+0x19f/0x210
arch/x86/entry/common.c:344
[<ffffffff85955362>] int_ret_from_sys_call+0x25/0x9f
arch/x86/entry/entry_64.S:281
---[ end trace 3e42717665ff2020 ]---


These WARNINGS always go with the original use-after-free reports. And
I was not able to reproduce this WARNING with commented out
sctp_association_destroy.

For the reference here is syzkaller program that triggers the WARNING.

r0 = socket(0xa, 0x1, 0x84)
mmap(&(0x7f0000000000)=nil, (0x10000), 0x3, 0x32, 0xffffffffffffffff, 0x0)
bind(r0, &(0x7f0000000000)="0a0033e049d02e70000000000000000000000000000000014c37ffc4",
0x1c)
connect(r0, &(0x7f0000001000)="020033d97f000001000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
0x80)
setsockopt$sock_int(r0, 0x1, 0x1d, &(0x7f0000001000+0x336)=0x1, 0x4)
listen(r0, 0xbb3)
r1 = accept(r0, &(0x7f0000003000+0xfd6)=nil, &(0x7f0000004000-0x2)=nil)

[Marcelo Ricardo Leitner]

Hi,

On Tue, Nov 24, 2015 at 10:15:57AM +0100, Dmitry Vyukov wrote:
>
> Call Trace:
> [<ffffffff8162131e>] __asan_report_load4_noabort+0x3e/0x40
> [<ffffffff8475ac76>] sctp_do_sm+0x42f6/0x4f60
> [<ffffffff847b50e9>] sctp_primitive_SHUTDOWN+0xa9/0xd0
> [<ffffffff847a1426>] sctp_close+0x616/0x790
> [<ffffffff8409bb0d>] inet_release+0xed/0x1c0 ./net/ipv4/af_inet.c:471
> [<ffffffff84192cc0>] inet6_release+0x50/0x70 ./net/ipv6/af_inet6.c:416
> [< inline >] constant_test_bit ././arch/x86/include/asm/bitops.h:321
> [<ffffffff83dc78cd>] sock_release+0x8d/0x200 ./net/socket.c:601
> [<ffffffff83dc7a56>] sock_close+0x16/0x20 ./net/socket.c:1188
> [<ffffffff81662f5d>] __fput+0x21d/0x6e0 ./fs/file_table.c:265
> [<ffffffff816634a5>] ____fput+0x15/0x20 ./fs/file_table.c:84
> [<ffffffff812a33d3>] task_work_run+0x163/0x1f0 ./include/trace/events/rcu.h:20
> [< inline >] __list_add ./include/linux/list.h:42

By any chance, did you have the pr_debug()s enabled?
Because that would trigger a use-after-free on debug_post_sfx()
macro expansion when the asoc is freed:

#define debug_post_sfx() \
pr_debug("%s[post-sfx]: error:%d, asoc:%p[%s]\n", __func__, error, \
asoc, sctp_state_tbl[(asoc && sctp_id2assoc(ep->base.sk, \
sctp_assoc2id(asoc))) ? asoc->state : SCTP_STATE_CLOSED])

Marcelo

[Dmitry Vyukov]

No, I don't. But pr_debug always computes its arguments. See no_printk
in printk.h. So this use-after-free happens for all users.

[Eric Dumazet]

>
> No, I don't. But pr_debug always computes its arguments. See no_printk
> in printk.h. So this use-after-free happens for all users.

Hmm.

pr_debug() should be a nop unless either DEBUG or CONFIG_DYNAMIC_DEBUG are set

On our production kernels, pr_debug() is a nop.

Can you double check ? Thanks !

[Dmitry Vyukov]

Why should it be nop? no_printk thing in printk.h pretty much
explicitly makes it not a nop...

Double-checked: debug_post_sfx leads to some generated code:

debug_post_sfx();
ffffffff8229f256: 48 8b 85 58 fe ff ff mov -0x1a8(%rbp),%rax
ffffffff8229f25d: 48 85 c0 test %rax,%rax
ffffffff8229f260: 74 24 je
ffffffff8229f286 <sctp_do_sm+0x176>
ffffffff8229f262: 8b b0 a8 00 00 00 mov 0xa8(%rax),%esi
ffffffff8229f268: 48 8b 85 60 fe ff ff mov -0x1a0(%rbp),%rax
ffffffff8229f26f: 44 89 85 74 fe ff ff mov %r8d,-0x18c(%rbp)
ffffffff8229f276: 48 8b 78 20 mov 0x20(%rax),%rdi
ffffffff8229f27a: e8 71 28 01 00 callq
ffffffff822b1af0 <sctp_id2assoc>
ffffffff8229f27f: 44 8b 85 74 fe ff ff mov -0x18c(%rbp),%r8d

return error;
}
ffffffff8229f286: 48 81 c4 a0 01 00 00 add $0x1a0,%rsp
ffffffff8229f28d: 44 89 c0 mov %r8d,%eax
ffffffff8229f290: 5b pop %rbx
ffffffff8229f291: 41 5c pop %r12
ffffffff8229f293: 41 5d pop %r13
ffffffff8229f295: 41 5e pop %r14
ffffffff8229f297: 41 5f pop %r15
ffffffff8229f299: 5d pop %rbp
ffffffff8229f29a: c3 retq

[Marcelo Ricardo Leitner]

On Thu, Dec 03, 2015 at 04:55:44PM +0100, Dmitry Vyukov wrote:
> On Thu, Dec 3, 2015 at 3:48 PM, Eric Dumazet <edum...@google.com> wrote:
> >>
> >> No, I don't. But pr_debug always computes its arguments. See no_printk
> >> in printk.h. So this use-after-free happens for all users.
> >
> > Hmm.
> >
> > pr_debug() should be a nop unless either DEBUG or CONFIG_DYNAMIC_DEBUG are set
> >
> > On our production kernels, pr_debug() is a nop.
> >
> > Can you double check ? Thanks !
>
>
> Why should it be nop? no_printk thing in printk.h pretty much
> explicitly makes it not a nop...
>
> Double-checked: debug_post_sfx leads to some generated code:

Oups. I was under that impression too, that it would do sanity-check
while being optimized out.

I'll think on a fix for this.

Thanks,
Marcelo

[Marcelo Ricardo Leitner]

These two are unrelated, actually.

Do you know if this accept() returned something? Seems so.
Seems to be originated on
sctp_v6_create_accept_sk() -> sctp_copy_sock():

void sctp_copy_sock(struct sock *newsk, struct sock *sk,
struct sctp_association *asoc)
{
struct inet_sock *inet = inet_sk(sk);
struct inet_sock *newinet;

newsk->sk_type = sk->sk_type;
newsk->sk_bound_dev_if = sk->sk_bound_dev_if;
newsk->sk_flags = sk->sk_flags; <---

As it enabled SO_TIMESTAMP on listening socket, this flag will be copied and
will trigger the second net_disable_timestamp() by the time the second
socket is destroyed, because it never had its enable counterpart called.

This also happens via sctp peeloff operation.

Marcelo

[Eric Dumazet]

This is a serious concern, because we let in the past lot of patches
converting traditional

#ifdef DEBUG
# define some_hand_coded_ugly_debug() printk( ...._
#else
# define some_hand_coded_ugly_debug()
#endif

On the premise pr_debug() would be a nop.

It seems it is not always the case. This is a very serious problem.

We probably have hundred of potential bugs, because few people
actually make sure all debugging stuff is correct,
like comments can be wrong because they are not updated properly as time flies.

It is definitely a nop for many cases.

+void eric_test_pr_debug(struct sock *sk)
+{
+ if (atomic_read(&sk->sk_omem_alloc))
+ pr_debug("%s: optmem leakage for sock %p\n",
+ __func__, sk);
+}

->

0000000000004740 <eric_test_pr_debug>:
4740: e8 00 00 00 00 callq 4745 <eric_test_pr_debug+0x5>
4741: R_X86_64_PC32 __fentry__-0x4
4745: 55 push %rbp
4746: 8b 87 24 01 00 00 mov 0x124(%rdi),%eax //
atomic_read() but nothing follows
474c: 48 89 e5 mov %rsp,%rbp
474f: 5d pop %rbp
4750: c3 retq

[Dmitry Vyukov]

I would expect that it is nop when argument evaluation does not have
side-effects. For example, for a load of a variable compiler will most
likely elide it (though, it does not have to elide it, because the
load is spelled in the code, so it can also legally emit the load and
doesn't use the result).
But if argument computation has side-effect (or compiler can't prove
otherwise), it must emit code. It must emit code for function calls
when the function is defined in a different translation unit, and for
volatile accesses (most likely including atomic accesses), etc

[Marcelo Ricardo Leitner]

Vlad, others,

It's been a long time but this was introduced by commit 914e1c8b6980
("sctp: Inherit all socket options from parent correctly."). This is not
very consistent with how other protocols work and it will be hard to
keep tracking a negative mask of flags that we can't copy.

I reviewed the list of options and I'm thinking that only
SO_BINDTODEVICE is worth copying, leaving the others for the application
to re-set, as it is for other protocols. So I'm thinking on simply:

- newsk->sk_flags = sk->sk_flags;
+ newsk->sk_flags = sk->sk_flags & SO_BINDTODEVICE;

in the above.

What do you think?

Marcelo

[Eric Dumazet]

On Thu, 2015-12-03 at 15:43 -0200, Marcelo Ricardo Leitner wrote:

> Vlad, others,
>
> It's been a long time but this was introduced by commit 914e1c8b6980
> ("sctp: Inherit all socket options from parent correctly."). This is not
> very consistent with how other protocols work and it will be hard to
> keep tracking a negative mask of flags that we can't copy.
>
> I reviewed the list of options and I'm thinking that only
> SO_BINDTODEVICE is worth copying, leaving the others for the application
> to re-set, as it is for other protocols. So I'm thinking on simply:
>
> - newsk->sk_flags = sk->sk_flags;
> + newsk->sk_flags = sk->sk_flags & SO_BINDTODEVICE;
>
> in the above.
>
> What do you think?

I think SO_BINDTODEVICE is not a flag ;)

#define SO_BINDTODEVICE 25

[Marcelo]

Oops, indeed!
Idea persists.
Thx!
--
Sent from mobile. Please excuse my brevity.

[Vlad Yasevich]

Hmm... sk_clone_lock() appears to copy the flags as well, so it would
appear the tcp accept() sockets would also have timestamping set.

I can see how we probably shouldn't being copying sk_flags as there isn't
much there that need to be set.

-vlad

[Marcelo]

Ahh right, through a memcpy. I completely missed that.

And later on it does:
if (sock_needs_netstamp(sk) &&
newsk->sk_flags & SK_FLAGS_TIMESTAMP)
net_enable_timestamp();

> I can see how we probably shouldn't being copying sk_flags as there isn't
> much there that need to be set.

I take that back then, we can enable timestamp like the above instead.
I'll test and post a patch soon.

Thanks,
Marcelo

[Aaron Conole]

Dmitry Vyukov <dvy...@google.com> writes:
> On Thu, Dec 3, 2015 at 6:02 PM, Eric Dumazet <edum...@google.com> wrote:
>> On Thu, Dec 3, 2015 at 7:55 AM, Dmitry Vyukov <dvy...@google.com> wrote:
>>> On Thu, Dec 3, 2015 at 3:48 PM, Eric Dumazet <edum...@google.com> wrote:
>>>>>
>>>>> No, I don't. But pr_debug always computes its arguments. See no_printk
>>>>> in printk.h. So this use-after-free happens for all users.
>>>>
>>>> Hmm.
>>>>
>>>> pr_debug() should be a nop unless either DEBUG or
>>>> CONFIG_DYNAMIC_DEBUG are set
>>>>
>>>> On our production kernels, pr_debug() is a nop.
>>>>
>>>> Can you double check ? Thanks !
>>>
>>>
>>> Why should it be nop? no_printk thing in printk.h pretty much
>>> explicitly makes it not a nop...

Because it was until commit 5264f2f75d8. It also violates my reading of
the following from printk.h:

* All of these will print unconditionally, although note that pr_debug()
* and other debug macros are compiled out unless either DEBUG is defined
* or CONFIG_DYNAMIC_DEBUG is set.

+1

>> #ifdef DEBUG
>> # define some_hand_coded_ugly_debug() printk( ...._
>> #else
>> # define some_hand_coded_ugly_debug()
>> #endif
>>
>> On the premise pr_debug() would be a nop.
>>
>> It seems it is not always the case. This is a very serious problem.

+1

This isn't 100% true. As you state, in order to reach the return 0, all
side effects must be evaluated. Load generally does not have side
effects, so it can be safely elided, but function() must be emitted.

However, that is _not_ required to get the desired warning emission on a
printf argument function, see http://pastebin.com/UHuaydkj for an
example.

I think that as a minimum, the following patch should be evaluted, but am
unsure to whom I should submit it (after I test):

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 9729565..cd24d2d 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -286,7 +286,7 @@ extern asmlinkage void dump_stack(void) __cold;
printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
#else
#define pr_debug(fmt, ...) \
- no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
+ ({ if(0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); 0;})
#endif

/*

[Joe Perches]

On Thu, 2015-12-03 at 13:52 -0500, Aaron Conole wrote:
> Dmitry Vyukov <dvy...@google.com> writes:
> > On Thu, Dec 3, 2015 at 6:02 PM, Eric Dumazet <edum...@google.com> wrote:
> > > On Thu, Dec 3, 2015 at 7:55 AM, Dmitry Vyukov <dvy...@google.com> wrote:

> > > > On Thu, Dec 3, 2015 at 3:48 PM, Eric Dumazet wrote:
> > > > > >
> > > > > > No, I don't. But pr_debug always computes its arguments. See no_printk
> > > > > > in printk.h. So this use-after-free happens for all users.
> > > > >
> > > > > Hmm.
> > > > >
> > > > > pr_debug() should be a nop unless either DEBUG or
> > > > > CONFIG_DYNAMIC_DEBUG are set
> > > > >
> > > > > On our production kernels, pr_debug() is a nop.
> > > > >
> > > > > Can you double check ? Thanks !
> > > >
> > > >
> > > > Why should it be nop? no_printk thing in printk.h pretty much
> > > > explicitly makes it not a nop...
>
> Because it was until commit 5264f2f75d8. It also violates my reading of
> the following from printk.h:
>
>  * All of these will print unconditionally, although note that pr_debug()
>  * and other debug macros are compiled out unless either DEBUG is defined
>  * or CONFIG_DYNAMIC_DEBUG is set.
>
> > > >
> > > > Double-checked: debug_post_sfx leads to some generated code:
> > > >
> > > >         debug_post_sfx();
> > > > ffffffff8229f256:       48 8b 85 58 fe ff ff    mov    -0x1a8(%rbp),%rax
> > > > ffffffff8229f25d:       48 85 c0                test   %rax,%rax
> > > > ffffffff8229f260:       74 24                   je
> > > > ffffffff8229f286

> > > > ffffffff8229f262:       8b b0 a8 00 00 00       mov    0xa8(%rax),%esi
> > > > ffffffff8229f268:       48 8b 85 60 fe ff ff    mov    -0x1a0(%rbp),%rax
> > > > ffffffff8229f26f:       44 89 85 74 fe ff ff    mov    %r8d,-0x18c(%rbp)
> > > > ffffffff8229f276:       48 8b 78 20             mov    0x20(%rax),%rdi
> > > > ffffffff8229f27a:       e8 71 28 01 00          callq
> > > > ffffffff822b1af0

> > > 0000000000004740 :

> > >     4740: e8 00 00 00 00       callq  4745

> > > 4741: R_X86_64_PC32 __fentry__-0x4
> > >     4745: 55                   push   %rbp
> > >     4746: 8b 87 24 01 00 00     mov    0x124(%rdi),%eax     //
> > > atomic_read()  but nothing follows
> > >     474c: 48 89 e5             mov    %rsp,%rbp
> > >     474f: 5d                   pop    %rbp
> > >     4750: c3                   retq
> >
> >
> >
> > I would expect that it is nop when argument evaluation does not have
> > side-effects. For example, for a load of a variable compiler will most
> > likely elide it (though, it does not have to elide it, because the
> > load is spelled in the code, so it can also legally emit the load and
> > doesn't use the result).
> > But if argument computation has side-effect (or compiler can't prove
> > otherwise), it must emit code. It must emit code for function calls
> > when the function is defined in a different translation unit, and for
> > volatile accesses (most likely including atomic accesses), etc
>
> This isn't 100% true. As you state, in order to reach the return 0, all
> side effects must be evaluated. Load generally does not have side
> effects, so it can be safely elided, but function() must be emitted.
>
> However, that is _not_ required to get the desired warning emission on a
> printf argument function, see http://pastebin.com/UHuaydkj for an
> example.
>
> I think that as a minimum, the following patch should be evaluted, but am
> unsure to whom I should submit it (after I test):

Andrew Morton <ak...@linux-foundation.org> (cc'd)

> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 9729565..cd24d2d 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -286,7 +286,7 @@ extern asmlinkage void dump_stack(void) __cold;
>         printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
>  #else
>  #define pr_debug(fmt, ...) \
> -       no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> +       ({ if(0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); 0;})

More common is to use do {} while (0) instead of a
statement expression.

I think it'd be good to change pr_debug and variants to
do { if (0) no_printk(...) } while (0)
or some other form that completely eliminates all the
side-effects/function evaluations.

I think the same should be true when CONFIG_PRINTK is
not enabled.

https://lkml.org/lkml/2014/12/3/696

[Jason Baron]

Agreed - the intention here is certainly to have no side effects. It
looks like 'no_printk()' is used in quite a few other places that would
benefit from this change. So we probably want a generic
'really_no_printk()' macro.

Thanks,

-Jason

>
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 9729565..cd24d2d 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -286,7 +286,7 @@ extern asmlinkage void dump_stack(void) __cold;
> printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> #else
> #define pr_debug(fmt, ...) \
> - no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> + ({ if(0) printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__); 0;})
> #endif
>
> /*

> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in

[Joe Perches]

On Thu, 2015-12-03 at 14:32 -0500, Jason Baron wrote:
> On 12/03/2015 01:52 PM, Aaron Conole wrote:
> > I think that as a minimum, the following patch should be evaluted,
> > but am unsure to whom I should submit it (after I test):
[]
> Agreed - the intention here is certainly to have no side effects. It
> looks like 'no_printk()' is used in quite a few other places that would
> benefit from this change. So we probably want a generic
> 'really_no_printk()' macro.

https://lkml.org/lkml/2012/6/17/231

[Jason Baron]

I don't see this in the tree. Also maybe we should just convert
no_printk() to do what your 'eliminated_printk()'. So we can convert all
users with this change?

Thanks,

-Jason

[Joe Perches]

On Thu, 2015-12-03 at 15:10 -0500, Jason Baron wrote:
> On 12/03/2015 03:03 PM, Joe Perches wrote:
> > On Thu, 2015-12-03 at 14:32 -0500, Jason Baron wrote:
> > > On 12/03/2015 01:52 PM, Aaron Conole wrote:
> > > > I think that as a minimum, the following patch should be evaluted,
> > > > but am unsure to whom I should submit it (after I test):
> > []
> > > Agreed - the intention here is certainly to have no side effects. It
> > > looks like 'no_printk()' is used in quite a few other places that would
> > > benefit from this change. So we probably want a generic
> > > 'really_no_printk()' macro.
> >
> > https://lkml.org/lkml/2012/6/17/231
>
> I don't see this in the tree.

It never got applied.

> Also maybe we should just convert
> no_printk() to do what your 'eliminated_printk()'.

Some of them at least.

> So we can convert all users with this change?

I don't think so, I think there are some
function evaluation/side effects that are
required.  I believe some do hardware I/O.

It'd be good to at least isolate them.

I'm not sure how to find them via some
automated tool/mechanism though.

I asked Julia Lawall about it once in this
thread: https://lkml.org/lkml/2014/12/3/696

[Jason Baron]

Seems rather fragile to have side effects that we rely
upon hidden in a printk().

Just convert them and see what breaks :)

[Joe Perches]

(adding lkml as this is likely better discussed there)

Yup.

> Just convert them and see what breaks :)

I appreciate your optimism.  It's very 1995.
Try it and see what happens.

[Dmitry Vyukov]

Whatever is the resolution for pr_debug, we still need to fix this
particular use-after-free. It affects stability of debug builds, gives
invalid debug output, prevents us from finding more bugs in SCTP. And
maybe somebody uses CONFIG_DYNAMIC_DEBUG in production.

[Dmitry Vyukov]

FWIW I enabled CONFIG_DYNAMIC_DEBUG on my fuzzer. Not that it gives
any particular guarantees, but still can catch some of these.

[Marcelo Ricardo Leitner]

Agreed. I'm already working on a fix for this particular use-after-free.

Another interesting thing about this is that sctp_do_sm() is called for
nearly every movement that happens on a sctp socket. Said that, that
always-running IDR search hidden on that debug statement do have some
nasty performance impact, specially because it's serialized on a
spinlock. This wouldn't be happening if it was fully ellided and would
be ok if that pr_debug() was really being printed, but not as it is.
Kudos to this report that I could notice this. I'm trying to fix this on
SCTP-side as well.

Marcelo

[Vlad Yasevich]

YUCK! I didn't really pay much attention to those debug macros before, but
debug_post_sfx() is truly awful.

This wasn't such a bad thing where these macros depended on CONFIG_SCTP_DEBUG,
but now that they are always built, we need fix them.

-vlad

[Aaron Conole]

I've proposed a patch to linux-kernel to fix them, but I don't think
it's really as bad as folks imagine. Ubuntu, RHEL, and Fedora all use
DYNAMIC_DEBUG configuration option, which means that the code is getting
emitted anyway (correctly, I'll add) and is shunted out by a dynamic
debug flag. So for the average user, it's not even really a blip.

That does mean there's a cool side-effect of the entire print-macro setup
which implies we execute less code when running with DYNAMIC_DEBUG=y in
the "normal" case. "Turn on the dynamic debugging config and watch
everything get better" isn't the worst mantra, is it? :)

[Dmitry Vyukov]

On Thu, Dec 3, 2015 at 9:51 PM, Joe Perches <j...@perches.com> wrote:

But Aaron says that DYNAMIC_DEBUG is enabled in most major
distributions, and all these side-effects don't happen with
DYNAMIC_DEBUG. This suggests that we can make these side-effects not
happen without DYNAMIC_DEBUG as well.
Or I am missing something here?

[Jason Baron]

When DYNAMIC_DEBUG is enabled we have this wrapper from
include/linux/dynamic_debug.h:

if (unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT))
<do debug stuff>

So the compiler is not emitting the side-effects in this
case.

>This suggests that we can make these side-effects not
> happen without DYNAMIC_DEBUG as well.
> Or I am missing something here?
>

When DYNAMIC_DEBUG is disabled we are instead replacing
pr_debug() with the 'no_printk()' function as you've pointed
out. We are changing this to emit no code at all:

http://marc.info/?l=linux-kernel&m=144918276518878&w=2

Thanks,

-Jason

[Joe Perches]

On Fri, 2015-12-04 at 11:47 -0500, Jason Baron wrote:
> When DYNAMIC_DEBUG is enabled we have this wrapper from
> include/linux/dynamic_debug.h:
>
> if (unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT))
> <do debug stuff>
>
> So the compiler is not emitting the side-effects in this
> case.

Huh?  Do I misunderstand what you are writing?

You are testing a variable that is not generally set
so the call is not being performed in the general case,
but the compiler can not elide the code.

If the variable was enabled via the control file, the
__dynamic_pr_debug would be performed with the
use-after-free.