Re: [syzbot] [net?] memory leak in tcp_md5_do_add

[Dmitry Safonov <dima@arista.com>]

[-- Attachment #1: Type: text/plain, Size: 5874 bytes --]

On 9/22/23 04:20, Eric Dumazet wrote:
> On Fri, Sep 22, 2023 at 1:15 AM Dmitry Safonov <dima@arista.com> wrote:
>>
>> Hi Eric,
>>
>> On 9/21/23 18:01, Dmitry Safonov wrote:
>>> On 9/21/23 17:59, Eric Dumazet wrote:
[..]
>>>> Dmitry, please take a look at this bug, we need to fix it before your
>>>> patch series.
>>>
>>> Sure, seems reasonable to me to fix before merging something on top.
>>
>> It seems to me that it's related to a race between RCU grace period and
>> kmemleak scan period. There seems to be a patch [1] that likely fixes
>> that, albeit I couldn't verify it as all my attempts to reproduce syzbot
>> issue produced only unrelated to TCP-MD5 log:
>>
> 
> I doubt this, looking at the repro, which seems to abuse a not often
> used feature of TCP (self connect)
> 
> # https://syzkaller.appspot.com/bug?id=323165b5fe193114de7a3a6a8bd16cf3a3c36ecf
> # See https://goo.gl/kgGztJ for information about syzkaller reproducers.
> #{"repeat":true,"procs":1,"slowdown":1,"sandbox":"none","sandbox_arg":0,"leak":true,"netdev":true,"close_fds":true,"usb":true}
> r0 = socket$inet6_tcp(0xa, 0x1, 0x0)
> setsockopt$inet6_tcp_TCP_MD5SIG(r0, 0x6, 0xe,
> &(0x7f0000000040)={@in6={{0xa, 0x0, 0x0, @local}}, 0x0, 0x0, 0x22,
> 0x0, "b05423587c18814d6b1a5f25671d09815a4687d637ffc958defc671aad3d4de8ac7d88560c759d600ab650c07ef0ef162b199da0d017fe6f0ae40cfb4e241cf9a990f20f6b8c2c070a61cfad8a2d2600"},
> 0xd8)
> connect$inet6(r0, &(0x7f0000000180)={0xa, 0x4001, 0x0, @ipv4={'\x00',
> '\xff\xff', @remote}}, 0x1c)
> dup(0xffffffffffffffff)
> setsockopt$SO_BINDTODEVICE(r0, 0x1, 0x19,
> &(0x7f00000001c0)='ip6_vti0\x00', 0xff4a)
> 
> 
> 
> You could not have KMEMLEAK in the kernel, and run the repro a thousand times.
> 
> Then compare /proc/slabinfo before/after.

Eric!

After some experiments, I'm still standing on the same RCU/kmemleak
race. Here's what I did:

1. I couldn't reproduce it on locally-build kernel with the same .config
in order to verify that the patch does fix this. Probably the toolchain
or any other small bits make a difference.

2. I can easily reproduce it with bzImage from syzcaller.

3. slabinfo does fluctuate for kmalloc-192 even without running any
reproducer, so it'd be hard to tell the difference.

4. I went running the reproducer in loop a hundred times:
# for i in $(seq 1 100) ; do ./repro ; dmesg -c >> ./dmesg.log ; done
the dmesg clean here is because pre-compiled ring-buffer is quite small
(I attach the full logs to this mail)

5. `cat /sys/kernel/debug/kmemleak` is empty, I presume it means that
the addresses that were reported later got removed from kmemleak
lists/tables on kfree().

6. Curious about addresses reported, I can see that some addresses were
reported multiple times, which means that slab got reused, rather than
leaked:
# grep tcp_md5_do_add -B9 dmesg.log | sed -n 's/.*unreferenced object
\([^ ]\+\) .*/\1/p' | sort | uniq -c | sort -n | tail -n 5
      2 0xffff8880174b96c0
      2 0xffff888017686900
      2 0xffff8880179fd720
      3 0xffff8880146a8600
      3 0xffff888015c226c0

See the logs for 0xffff888015c226c0 address (you can view them in dmesg
that I attach):
https://gist.github.com/0x7f454c46/dcc7936392a51a789a235eb73df1598c

7. Well, OK, maybe at least one of the addresses reported was leaked?
In order to check that, I did:
# cat dmesg.log  | grep tcp_md5_do_add -B9  | sed -n 's/.*unreferenced
object \([^ ]\+\) .*/\1/p' | sort | uniq > addresses
# dmesg -c ; for i in $(cat addresses) ; do echo "dump=$i" >
/sys/kernel/debug/kmemleak ; dmesg -c >> addresses.kmemleak ; done

I attach addresses.kmemleak: the slabs were reused or weren't allocated
(I presume, the "Unknown object at 0xffff888019cdcdc0" means that slab
is free).

8. Now that I verified that kmemleak was misreporting those addresses, I
went on my regular TCP-AO selftests, added one for TCP self-connect and
with ftrace I can clearly see that md5 keys/info is deallocated:
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 5/5   #P:2
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
 self-connect_ip-2125    [000] ...1.  6108.468401: tcp_md5_do_add
<-tcp_v4_parse_md5_keys
 self-connect_ip-2125    [000] ...1.  6108.468727: __tcp_md5_do_add
<-tcp_md5_do_add
 self-connect_ip-2125    [000] ...1.  6108.471276: tcp_clear_md5_list
<-tcp_v4_destroy_sock
    kworker/u5:1-2108    [000] ..s1.  6108.475633:
tcp_md5sig_info_free_rcu <-rcu_core
          <idle>-0       [000] ..s2.  6108.598342: tcp_md5_twsk_free_rcu
<-rcu_core

So, from source code point of view: the test opens socket, sends SYN,
receives SYN straight away and kernel decides that it's
simultaneous/fast open case. It sends SYN-ACK and establishes as normal.
On socket destruction, TCP-MD5 key gets destroyed the regular way.
Nothing seems special in this TCP self-connect case.

9. The only interesting part in this experiment is that now I have a TCP
self-connect selftest, that by its nature tests simultaneous open, which
as I expected works with TCP-MD5, but not with TCP-AO:
[ 3412.559472] TCP: AO hash mismatch for (127.0.0.1, 7010)->(127.0.0.1,
7010) SA
[ 4115.964926] TCP: AO hash mismatch for [::1]:7010->[::1]:7010 SA
L3index: 0

It was expected as tcp_inbound_ao_hash() has
:	/* Fast-path */
:	/* TODO: fix fastopen and simultaneous open (TCPF_SYN_RECV) */

Going to fix this for TCP-AO-v13.

Please, let me know if this explanation/investigation looks good to you,
so that I can proceed with v13.

Thanks,
             Dmitry

[-- Attachment #2: dmesg.log.xz --]
[-- Type: application/x-xz, Size: 672552 bytes --]

[-- Attachment #3: addresses.kmemleak.xz --]
[-- Type: application/x-xz, Size: 6696 bytes --]