Re: [RFC] mm/kasan: Add Allocation, Free, Error timestamps to KASAN report

[Juntong Deng <juntong.deng@outlook.com>]

On 2023/10/30 14:29, Dmitry Vyukov wrote:
> On Sun, 29 Oct 2023 at 10:05, Juntong Deng <juntong.deng@outlook.com> wrote:
>>
>> On 2023/10/26 3:22, Andrey Konovalov wrote:
>>> On Tue, Oct 17, 2023 at 9:40 PM Juntong Deng <juntong.deng@outlook.com> wrote:
>>>>
>>>> The idea came from the bug I was fixing recently,
>>>> 'KASAN: slab-use-after-free Read in tls_encrypt_done'.
>>>>
>>>> This bug is caused by subtle race condition, where the data structure
>>>> is freed early on another CPU, resulting in use-after-free.
>>>>
>>>> Like this bug, some of the use-after-free bugs are caused by race
>>>> condition, but it is not easy to quickly conclude that the cause of the
>>>> use-after-free is race condition if only looking at the stack trace.
>>>>
>>>> I did not think this use-after-free was caused by race condition at the
>>>> beginning, it took me some time to read the source code carefully and
>>>> think about it to determine that it was caused by race condition.
>>>>
>>>> By adding timestamps for Allocation, Free, and Error to the KASAN
>>>> report, it will be much easier to determine if use-after-free is
>>>> caused by race condition.
>>>
>>> An alternative would be to add the CPU number to the alloc/free stack
>>> traces. Something like:
>>>
>>> Allocated by task 42 on CPU 2:
>>> (stack trace)
>>>
>>> The bad access stack trace already prints the CPU number.
>>
>> Yes, that is a great idea and the CPU number would help a lot.
>>
>> But I think the CPU number cannot completely replace the free timestamp,
>> because some freeing really should be done at another CPU.
>>
>> We need the free timestamp to help us distinguish whether it was freed
>> a long time ago or whether it was caused to be freed during the
>> current operation.
>>
>> I think both the CPU number and the timestamp should be displayed, more
>> information would help us find the real cause of the error faster.
>>
>> Should I implement these features?
> 
> Hi Juntong,
> 
> There is also an aspect of memory consumption. KASAN headers increase
> the size of every heap object. So we tried to keep them as compact as
> possible. At some point CPU numbers and timestamps (IIRC) were already
> part of the header, but we removed them to shrink the header to 16
> bytes.
> PID gives a good approximation of potential races. I usually look at
> PIDs to understand if it's a "plain old single-threaded
> use-after-free", or free and access happened in different threads.
> Re timestamps, I see you referenced a syzbot report. With syzkaller
> most timestamps will be very close even for non-racing case.
> So if this is added, this should be added at least under a separate config.
> 
> If you are looking for potential KASAN improvements, here is a good list:
> https://bugzilla.kernel.org/buglist.cgi?bug_status=__open__&component=Sanitizers&list_id=1134168&product=Memory%20Management

Hi Dmitry,

I think PID cannot completely replace timestamp for reason similar to
CPU number, some frees really should be done in another thread, but it
is difficult for us to distinguish if it is a free that was done some
time ago, or under subtle race conditions.

As to whether most of the timestamps will be very close even for
non-racing case, this I am not sure, because I do not have
enough samples.

I agree that these features should be in a separate config and
the user should be free to choose whether to enable them or not.

We can divide KASAN into normal mode and depth mode. Normal mode
records only minimal critical information, while depth mode records
more potentially useful information.

Also, honestly, I think a small amount of extra memory consumption
should not stop us from recording more information.

Because if someone enables KASAN for debugging, then memory consumption
and performance are no longer his main concern.