Potential data race in uart_ioctl

Potential data race in uart_ioctl

[Andrey Konovalov]

Hi!

We are working on a dynamic data race detector for the Linux kernel
called KernelThreadSanitizer (ktsan)
(https://github.com/google/ktsan/wiki).

While booting the kernel (upstream revision 21bdb584af8c) we got a report:

==================================================================
ThreadSanitizer: data-race in uart_ioctl

Read of size 8 by thread T424 (K971):
 [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
drivers/tty/serial/serial_core.c:1216
 [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
 [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
 [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
 [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
 [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
 [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
arch/x86/entry/entry_64.S:186
DBG: cpu = ffff88063fc1fe68
DBG: cpu id = 0

Previous write of size 8 by thread T422 (K970):
 [<ffffffff816737ef>] uart_open+0x12f/0x220
drivers/tty/serial/serial_core.c:1629
 [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
 [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
 [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
 [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
 [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
 [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
 [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
 [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
 [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
 [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
 [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
arch/x86/entry/entry_64.S:186
DBG: cpu = ffff88063fd1fe68

DBG: addr: ffff8801d2a0ce88
DBG: first offset: 0, second offset: 0
DBG: T424 clock: {T424: 211057, T422: 275728}
DBG: T422 clock: {T422: 275819}
==================================================================

It seems that one thread reads and uses tty->driver_data while it's
being initialized in another one. The second thread holds port->mutex,
but the first one does a few accesses to tty->driver_data before
locking it.

Could you confirm if this is a real race?

Thanks!

Re: Potential data race in uart_ioctl

[Peter Hurley]

Hi Andrey,

On 08/25/2015 08:17 AM, Andrey Konovalov wrote:
> Hi!
> 
> We are working on a dynamic data race detector for the Linux kernel
> called KernelThreadSanitizer (ktsan)
> (https://github.com/google/ktsan/wiki).
> 
> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
> 
> ==================================================================
> ThreadSanitizer: data-race in uart_ioctl
> 
> Read of size 8 by thread T424 (K971):
>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
> drivers/tty/serial/serial_core.c:1216
>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
> arch/x86/entry/entry_64.S:186
> DBG: cpu = ffff88063fc1fe68
> DBG: cpu id = 0
> 
> Previous write of size 8 by thread T422 (K970):
>  [<ffffffff816737ef>] uart_open+0x12f/0x220
> drivers/tty/serial/serial_core.c:1629
>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
> arch/x86/entry/entry_64.S:186
> DBG: cpu = ffff88063fd1fe68
> 
> DBG: addr: ffff8801d2a0ce88
> DBG: first offset: 0, second offset: 0
> DBG: T424 clock: {T424: 211057, T422: 275728}
> DBG: T422 clock: {T422: 275819}
> ==================================================================
> 
> It seems that one thread reads and uses tty->driver_data while it's
> being initialized in another one. The second thread holds port->mutex,
> but the first one does a few accesses to tty->driver_data before
> locking it.
> 
> Could you confirm if this is a real race?

Although I don't understand what triggers ktsan to signal a race
condition, this doesn't appear to be an actual race.

For an ioctl() syscall to act on any given tty requires a successful
open() syscall to have nearly completed (do_sys_open() => fd_install()
initializes the file descriptor; ioctl() => fdget() derefs the descriptor).

Perhaps what's tripping the race detection is that 2nd and subsequent
opens also (redundantly) write the same values as from the first open?

Regards,
Peter Hurley

Re: Potential data race in uart_ioctl

[Dmitry Vyukov]

On Tue, Aug 25, 2015 at 8:26 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
> Hi Andrey,
>
> On 08/25/2015 08:17 AM, Andrey Konovalov wrote:
>> Hi!
>>
>> We are working on a dynamic data race detector for the Linux kernel
>> called KernelThreadSanitizer (ktsan)
>> (https://github.com/google/ktsan/wiki).
>>
>> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
>>
>> ==================================================================
>> ThreadSanitizer: data-race in uart_ioctl
>>
>> Read of size 8 by thread T424 (K971):
>>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
>> drivers/tty/serial/serial_core.c:1216
>>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>> arch/x86/entry/entry_64.S:186
>> DBG: cpu = ffff88063fc1fe68
>> DBG: cpu id = 0
>>
>> Previous write of size 8 by thread T422 (K970):
>>  [<ffffffff816737ef>] uart_open+0x12f/0x220
>> drivers/tty/serial/serial_core.c:1629
>>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>> arch/x86/entry/entry_64.S:186
>> DBG: cpu = ffff88063fd1fe68
>>
>> DBG: addr: ffff8801d2a0ce88
>> DBG: first offset: 0, second offset: 0
>> DBG: T424 clock: {T424: 211057, T422: 275728}
>> DBG: T422 clock: {T422: 275819}
>> ==================================================================
>>
>> It seems that one thread reads and uses tty->driver_data while it's
>> being initialized in another one. The second thread holds port->mutex,
>> but the first one does a few accesses to tty->driver_data before
>> locking it.
>>
>> Could you confirm if this is a real race?
>
> Although I don't understand what triggers ktsan to signal a race
> condition, this doesn't appear to be an actual race.
>
> For an ioctl() syscall to act on any given tty requires a successful
> open() syscall to have nearly completed (do_sys_open() => fd_install()
> initializes the file descriptor; ioctl() => fdget() derefs the descriptor).
>
> Perhaps what's tripping the race detection is that 2nd and subsequent
> opens also (redundantly) write the same values as from the first open?

Since we use a fuzzer, yes, it is possible that open is called twice.

Re: Potential data race in uart_ioctl

[Dmitry Vyukov]

On Tue, Aug 25, 2015 at 8:32 PM, Dmitry Vyukov <dvyukov@google.com> wrote:
> On Tue, Aug 25, 2015 at 8:26 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
>> Hi Andrey,
>>
>> On 08/25/2015 08:17 AM, Andrey Konovalov wrote:
>>> Hi!
>>>
>>> We are working on a dynamic data race detector for the Linux kernel
>>> called KernelThreadSanitizer (ktsan)
>>> (https://github.com/google/ktsan/wiki).
>>>
>>> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
>>>
>>> ==================================================================
>>> ThreadSanitizer: data-race in uart_ioctl
>>>
>>> Read of size 8 by thread T424 (K971):
>>>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
>>> drivers/tty/serial/serial_core.c:1216
>>>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>>>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>>>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>>>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>>>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>> arch/x86/entry/entry_64.S:186
>>> DBG: cpu = ffff88063fc1fe68
>>> DBG: cpu id = 0
>>>
>>> Previous write of size 8 by thread T422 (K970):
>>>  [<ffffffff816737ef>] uart_open+0x12f/0x220
>>> drivers/tty/serial/serial_core.c:1629
>>>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>>>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>>>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>>>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>>>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>>>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>>>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>>>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>>>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>>>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>> arch/x86/entry/entry_64.S:186
>>> DBG: cpu = ffff88063fd1fe68
>>>
>>> DBG: addr: ffff8801d2a0ce88
>>> DBG: first offset: 0, second offset: 0
>>> DBG: T424 clock: {T424: 211057, T422: 275728}
>>> DBG: T422 clock: {T422: 275819}
>>> ==================================================================
>>>
>>> It seems that one thread reads and uses tty->driver_data while it's
>>> being initialized in another one. The second thread holds port->mutex,
>>> but the first one does a few accesses to tty->driver_data before
>>> locking it.
>>>
>>> Could you confirm if this is a real race?
>>
>> Although I don't understand what triggers ktsan to signal a race
>> condition, this doesn't appear to be an actual race.
>>
>> For an ioctl() syscall to act on any given tty requires a successful
>> open() syscall to have nearly completed (do_sys_open() => fd_install()
>> initializes the file descriptor; ioctl() => fdget() derefs the descriptor).
>>
>> Perhaps what's tripping the race detection is that 2nd and subsequent
>> opens also (redundantly) write the same values as from the first open?
>
> Since we use a fuzzer, yes, it is possible that open is called twice.

Oh, no, sorry, this happens during booting.
The race is on tty_struct, which is probably shared between several
file descriptors.

Re: Potential data race in uart_ioctl

[Peter Hurley]

On 08/25/2015 02:38 PM, Dmitry Vyukov wrote:
> On Tue, Aug 25, 2015 at 8:32 PM, Dmitry Vyukov <dvyukov@google.com> wrote:
>> On Tue, Aug 25, 2015 at 8:26 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
>>> On 08/25/2015 08:17 AM, Andrey Konovalov wrote:
>>>> Hi!
>>>>
>>>> We are working on a dynamic data race detector for the Linux kernel
>>>> called KernelThreadSanitizer (ktsan)
>>>> (https://github.com/google/ktsan/wiki).
>>>>
>>>> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
>>>>
>>>> ==================================================================
>>>> ThreadSanitizer: data-race in uart_ioctl
>>>>
>>>> Read of size 8 by thread T424 (K971):
>>>>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
>>>> drivers/tty/serial/serial_core.c:1216
>>>>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>>>>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>>>>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>>>>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>>>>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>> arch/x86/entry/entry_64.S:186
>>>> DBG: cpu = ffff88063fc1fe68
>>>> DBG: cpu id = 0
>>>>
>>>> Previous write of size 8 by thread T422 (K970):
>>>>  [<ffffffff816737ef>] uart_open+0x12f/0x220
>>>> drivers/tty/serial/serial_core.c:1629
>>>>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>>>>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>>>>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>>>>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>>>>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>>>>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>>>>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>>>>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>>>>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>>>>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>> arch/x86/entry/entry_64.S:186
>>>> DBG: cpu = ffff88063fd1fe68
>>>>
>>>> DBG: addr: ffff8801d2a0ce88
>>>> DBG: first offset: 0, second offset: 0
>>>> DBG: T424 clock: {T424: 211057, T422: 275728}
>>>> DBG: T422 clock: {T422: 275819}
>>>> ==================================================================
>>>>
>>>> It seems that one thread reads and uses tty->driver_data while it's
>>>> being initialized in another one. The second thread holds port->mutex,
>>>> but the first one does a few accesses to tty->driver_data before
>>>> locking it.
>>>>
>>>> Could you confirm if this is a real race?
>>>
>>> Although I don't understand what triggers ktsan to signal a race
>>> condition, this doesn't appear to be an actual race.
>>>
>>> For an ioctl() syscall to act on any given tty requires a successful
>>> open() syscall to have nearly completed (do_sys_open() => fd_install()
>>> initializes the file descriptor; ioctl() => fdget() derefs the descriptor).
>>>
>>> Perhaps what's tripping the race detection is that 2nd and subsequent
>>> opens also (redundantly) write the same values as from the first open?
>>
>> Since we use a fuzzer, yes, it is possible that open is called twice.
> 
> Oh, no, sorry, this happens during booting.
> The race is on tty_struct, which is probably shared between several
> file descriptors.

Yep, but there is 1:1 correspondence between tty_struct and uart_state;
so once the first open() initializes tty->driver_data, subsequent opens
are just re-writing the same value for tty->driver_data.

Is ktsan just triggering on the fact there is a memory write, without
checking the value has changed?

Regards,
Peter Hurley

Re: Potential data race in uart_ioctl

[Dmitry Vyukov]

On Tue, Aug 25, 2015 at 9:03 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
> On 08/25/2015 02:38 PM, Dmitry Vyukov wrote:
>> On Tue, Aug 25, 2015 at 8:32 PM, Dmitry Vyukov <dvyukov@google.com> wrote:
>>> On Tue, Aug 25, 2015 at 8:26 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
>>>> On 08/25/2015 08:17 AM, Andrey Konovalov wrote:
>>>>> Hi!
>>>>>
>>>>> We are working on a dynamic data race detector for the Linux kernel
>>>>> called KernelThreadSanitizer (ktsan)
>>>>> (https://github.com/google/ktsan/wiki).
>>>>>
>>>>> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
>>>>>
>>>>> ==================================================================
>>>>> ThreadSanitizer: data-race in uart_ioctl
>>>>>
>>>>> Read of size 8 by thread T424 (K971):
>>>>>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
>>>>> drivers/tty/serial/serial_core.c:1216
>>>>>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>>>>>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>>>>>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>>>>>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>>>>>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>>> arch/x86/entry/entry_64.S:186
>>>>> DBG: cpu = ffff88063fc1fe68
>>>>> DBG: cpu id = 0
>>>>>
>>>>> Previous write of size 8 by thread T422 (K970):
>>>>>  [<ffffffff816737ef>] uart_open+0x12f/0x220
>>>>> drivers/tty/serial/serial_core.c:1629
>>>>>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>>>>>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>>>>>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>>>>>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>>>>>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>>>>>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>>>>>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>>>>>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>>>>>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>>>>>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>>> arch/x86/entry/entry_64.S:186
>>>>> DBG: cpu = ffff88063fd1fe68
>>>>>
>>>>> DBG: addr: ffff8801d2a0ce88
>>>>> DBG: first offset: 0, second offset: 0
>>>>> DBG: T424 clock: {T424: 211057, T422: 275728}
>>>>> DBG: T422 clock: {T422: 275819}
>>>>> ==================================================================
>>>>>
>>>>> It seems that one thread reads and uses tty->driver_data while it's
>>>>> being initialized in another one. The second thread holds port->mutex,
>>>>> but the first one does a few accesses to tty->driver_data before
>>>>> locking it.
>>>>>
>>>>> Could you confirm if this is a real race?
>>>>
>>>> Although I don't understand what triggers ktsan to signal a race
>>>> condition, this doesn't appear to be an actual race.
>>>>
>>>> For an ioctl() syscall to act on any given tty requires a successful
>>>> open() syscall to have nearly completed (do_sys_open() => fd_install()
>>>> initializes the file descriptor; ioctl() => fdget() derefs the descriptor).
>>>>
>>>> Perhaps what's tripping the race detection is that 2nd and subsequent
>>>> opens also (redundantly) write the same values as from the first open?
>>>
>>> Since we use a fuzzer, yes, it is possible that open is called twice.
>>
>> Oh, no, sorry, this happens during booting.
>> The race is on tty_struct, which is probably shared between several
>> file descriptors.
>
> Yep, but there is 1:1 correspondence between tty_struct and uart_state;
> so once the first open() initializes tty->driver_data, subsequent opens
> are just re-writing the same value for tty->driver_data.
>
> Is ktsan just triggering on the fact there is a memory write, without
> checking the value has changed?

Yes, that is correct. Ktsan is based on C memory model which says that
any write racing with other memory access leads to undefined behavior.

As far as I see the setup is quite complex and not just writes to
tty->driver_data. For example, it also calls uart_startup which does
set_bit(TTY_IO_ERROR, &tty->flags) on the tty. Can't that lead to some
issues? E.g. we set TTY_IO_ERROR, but since tty is already used by
other threads, operations on the tty in other threads will spuriously
fail.

195 static int uart_startup(struct tty_struct *tty, struct uart_state *state,
196                 int init_hw)
197 {
198         struct tty_port *port = &state->port;
199         int retval;
200
201         if (port->flags & ASYNC_INITIALIZED)
202                 return 0;
203
204         /*
205          * Set the TTY IO error marker - we will only clear this
206          * once we have successfully opened the port.
207          */
208         set_bit(TTY_IO_ERROR, &tty->flags);
209
210         retval = uart_port_startup(tty, state, init_hw);
211         if (!retval) {
212                 set_bit(ASYNCB_INITIALIZED, &port->flags);
213                 clear_bit(TTY_IO_ERROR, &tty->flags);
214         } else if (retval > 0)
215                 retval = 0;
216
217         return retval;
218 }

Re: Potential data race in uart_ioctl

[Peter Hurley]

On 08/25/2015 03:50 PM, Dmitry Vyukov wrote:
> On Tue, Aug 25, 2015 at 9:03 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
>> On 08/25/2015 02:38 PM, Dmitry Vyukov wrote:
>>> On Tue, Aug 25, 2015 at 8:32 PM, Dmitry Vyukov <dvyukov@google.com> wrote:
>>>> On Tue, Aug 25, 2015 at 8:26 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
>>>>> On 08/25/2015 08:17 AM, Andrey Konovalov wrote:
>>>>>> Hi!
>>>>>>
>>>>>> We are working on a dynamic data race detector for the Linux kernel
>>>>>> called KernelThreadSanitizer (ktsan)
>>>>>> (https://github.com/google/ktsan/wiki).
>>>>>>
>>>>>> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
>>>>>>
>>>>>> ==================================================================
>>>>>> ThreadSanitizer: data-race in uart_ioctl
>>>>>>
>>>>>> Read of size 8 by thread T424 (K971):
>>>>>>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
>>>>>> drivers/tty/serial/serial_core.c:1216
>>>>>>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>>>>>>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>>>>>>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>>>>>>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>>>>>>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>>>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>>>> arch/x86/entry/entry_64.S:186
>>>>>> DBG: cpu = ffff88063fc1fe68
>>>>>> DBG: cpu id = 0
>>>>>>
>>>>>> Previous write of size 8 by thread T422 (K970):
>>>>>>  [<ffffffff816737ef>] uart_open+0x12f/0x220
>>>>>> drivers/tty/serial/serial_core.c:1629
>>>>>>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>>>>>>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>>>>>>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>>>>>>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>>>>>>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>>>>>>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>>>>>>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>>>>>>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>>>>>>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>>>>>>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>>>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>>>> arch/x86/entry/entry_64.S:186
>>>>>> DBG: cpu = ffff88063fd1fe68
>>>>>>
>>>>>> DBG: addr: ffff8801d2a0ce88
>>>>>> DBG: first offset: 0, second offset: 0
>>>>>> DBG: T424 clock: {T424: 211057, T422: 275728}
>>>>>> DBG: T422 clock: {T422: 275819}
>>>>>> ==================================================================
>>>>>>
>>>>>> It seems that one thread reads and uses tty->driver_data while it's
>>>>>> being initialized in another one. The second thread holds port->mutex,
>>>>>> but the first one does a few accesses to tty->driver_data before
>>>>>> locking it.
>>>>>>
>>>>>> Could you confirm if this is a real race?
>>>>>
>>>>> Although I don't understand what triggers ktsan to signal a race
>>>>> condition, this doesn't appear to be an actual race.
>>>>>
>>>>> For an ioctl() syscall to act on any given tty requires a successful
>>>>> open() syscall to have nearly completed (do_sys_open() => fd_install()
>>>>> initializes the file descriptor; ioctl() => fdget() derefs the descriptor).
>>>>>
>>>>> Perhaps what's tripping the race detection is that 2nd and subsequent
>>>>> opens also (redundantly) write the same values as from the first open?
>>>>
>>>> Since we use a fuzzer, yes, it is possible that open is called twice.
>>>
>>> Oh, no, sorry, this happens during booting.
>>> The race is on tty_struct, which is probably shared between several
>>> file descriptors.
>>
>> Yep, but there is 1:1 correspondence between tty_struct and uart_state;
>> so once the first open() initializes tty->driver_data, subsequent opens
>> are just re-writing the same value for tty->driver_data.
>>
>> Is ktsan just triggering on the fact there is a memory write, without
>> checking the value has changed?
> 
> Yes, that is correct. Ktsan is based on C memory model which says that
> any write racing with other memory access leads to undefined behavior.

The Linux kernel largely ignores the C memory model definition, and
relies on practical compiler behavior.

So-called 'data races' are common in kernel code.

> As far as I see the setup is quite complex and not just writes to
> tty->driver_data.

Yes, vfs => tty => serial core => uart driver is a (necessarily) complicated
stack.

> For example, it also calls uart_startup which does
> set_bit(TTY_IO_ERROR, &tty->flags) on the tty. Can't that lead to some
> issues?

No.

> E.g. we set TTY_IO_ERROR, but since tty is already used by
> other threads, operations on the tty in other threads will spuriously
> fail.

See below.

> 195 static int uart_startup(struct tty_struct *tty, struct uart_state *state,
> 196                 int init_hw)
> 197 {
> 198         struct tty_port *port = &state->port;
> 199         int retval;
> 200
> 201         if (port->flags & ASYNC_INITIALIZED)
> 202                 return 0;

Subsequent opens return success here (note below how the ASYNCB_INITIALIZED bit
is set in tty->flags if uart_port_startup() returned success from the earlier
open ?)

Regards,
Peter Hurley

> 203
> 204         /*
> 205          * Set the TTY IO error marker - we will only clear this
> 206          * once we have successfully opened the port.
> 207          */
> 208         set_bit(TTY_IO_ERROR, &tty->flags);
> 209
> 210         retval = uart_port_startup(tty, state, init_hw);
> 211         if (!retval) {
> 212                 set_bit(ASYNCB_INITIALIZED, &port->flags);
> 213                 clear_bit(TTY_IO_ERROR, &tty->flags);
> 214         } else if (retval > 0)
> 215                 retval = 0;
> 216
> 217         return retval;
> 218 }
> 

Re: Potential data race in uart_ioctl

[Dmitry Vyukov]

On Tue, Aug 25, 2015 at 10:58 PM, Peter Hurley <peter@hurleysoftware.com> wrote:
>>>>>>> Hi!
>>>>>>>
>>>>>>> We are working on a dynamic data race detector for the Linux kernel
>>>>>>> called KernelThreadSanitizer (ktsan)
>>>>>>> (https://github.com/google/ktsan/wiki).
>>>>>>>
>>>>>>> While booting the kernel (upstream revision 21bdb584af8c) we got a report:
>>>>>>>
>>>>>>> ==================================================================
>>>>>>> ThreadSanitizer: data-race in uart_ioctl
>>>>>>>
>>>>>>> Read of size 8 by thread T424 (K971):
>>>>>>>  [<ffffffff81673c56>] uart_ioctl+0x36/0x11e0
>>>>>>> drivers/tty/serial/serial_core.c:1216
>>>>>>>  [<ffffffff81643802>] tty_ioctl+0x4f2/0x11d0 drivers/tty/tty_io.c:2924
>>>>>>>  [<     inlined    >] do_vfs_ioctl+0x44a/0x750 vfs_ioctl fs/ioctl.c:43
>>>>>>>  [<ffffffff8127b0ca>] do_vfs_ioctl+0x44a/0x750 fs/ioctl.c:607
>>>>>>>  [<     inlined    >] SyS_ioctl+0x79/0xa0 SYSC_ioctl fs/ioctl.c:622
>>>>>>>  [<ffffffff8127b449>] SyS_ioctl+0x79/0xa0 fs/ioctl.c:613
>>>>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>>>>> arch/x86/entry/entry_64.S:186
>>>>>>> DBG: cpu = ffff88063fc1fe68
>>>>>>> DBG: cpu id = 0
>>>>>>>
>>>>>>> Previous write of size 8 by thread T422 (K970):
>>>>>>>  [<ffffffff816737ef>] uart_open+0x12f/0x220
>>>>>>> drivers/tty/serial/serial_core.c:1629
>>>>>>>  [<ffffffff81645be2>] tty_open+0x192/0x8f0 drivers/tty/tty_io.c:2105
>>>>>>>  [<ffffffff812628fc>] chrdev_open+0x13c/0x290 fs/char_dev.c:388
>>>>>>>  [<ffffffff812582fc>] do_dentry_open+0x3ac/0x550 fs/open.c:736
>>>>>>>  [<ffffffff81259d68>] vfs_open+0xb8/0xe0 fs/open.c:853
>>>>>>>  [<     inlined    >] path_openat+0x81c/0x2440 do_last fs/namei.c:3163
>>>>>>>  [<ffffffff81272f1c>] path_openat+0x81c/0x2440 fs/namei.c:3295
>>>>>>>  [<ffffffff8127656a>] do_filp_open+0xfa/0x170 fs/namei.c:3330
>>>>>>>  [<ffffffff8125a243>] do_sys_open+0x183/0x2b0 fs/open.c:1025
>>>>>>>  [<     inlined    >] SyS_open+0x35/0x50 SYSC_open fs/open.c:1043
>>>>>>>  [<ffffffff8125a3a5>] SyS_open+0x35/0x50 fs/open.c:1038
>>>>>>>  [<ffffffff81eae0ae>] entry_SYSCALL_64_fastpath+0x12/0x71
>>>>>>> arch/x86/entry/entry_64.S:186
>>>>>>> DBG: cpu = ffff88063fd1fe68
>>>>>>>
>>>>>>> DBG: addr: ffff8801d2a0ce88
>>>>>>> DBG: first offset: 0, second offset: 0
>>>>>>> DBG: T424 clock: {T424: 211057, T422: 275728}
>>>>>>> DBG: T422 clock: {T422: 275819}
>>>>>>> ==================================================================
>>>>>>>
>>>>>>> It seems that one thread reads and uses tty->driver_data while it's
>>>>>>> being initialized in another one. The second thread holds port->mutex,
>>>>>>> but the first one does a few accesses to tty->driver_data before
>>>>>>> locking it.
>>>>>>>
>>>>>>> Could you confirm if this is a real race?
>>>>>>
>>>>>> Although I don't understand what triggers ktsan to signal a race
>>>>>> condition, this doesn't appear to be an actual race.
>>>>>>
>>>>>> For an ioctl() syscall to act on any given tty requires a successful
>>>>>> open() syscall to have nearly completed (do_sys_open() => fd_install()
>>>>>> initializes the file descriptor; ioctl() => fdget() derefs the descriptor).
>>>>>>
>>>>>> Perhaps what's tripping the race detection is that 2nd and subsequent
>>>>>> opens also (redundantly) write the same values as from the first open?
>>>>>
>>>>> Since we use a fuzzer, yes, it is possible that open is called twice.
>>>>
>>>> Oh, no, sorry, this happens during booting.
>>>> The race is on tty_struct, which is probably shared between several
>>>> file descriptors.
>>>
>>> Yep, but there is 1:1 correspondence between tty_struct and uart_state;
>>> so once the first open() initializes tty->driver_data, subsequent opens
>>> are just re-writing the same value for tty->driver_data.
>>>
>>> Is ktsan just triggering on the fact there is a memory write, without
>>> checking the value has changed?
>>
>> Yes, that is correct. Ktsan is based on C memory model which says that
>> any write racing with other memory access leads to undefined behavior.
>
> The Linux kernel largely ignores the C memory model definition, and
> relies on practical compiler behavior.
>
> So-called 'data races' are common in kernel code.

Yeah, I know. But the problem is that with the kernel model it is not
possible to automatically find real harmful race conditions, so we
have to stick with something that allows that.


>> As far as I see the setup is quite complex and not just writes to
>> tty->driver_data.
>
> Yes, vfs => tty => serial core => uart driver is a (necessarily) complicated
> stack.
>
>> For example, it also calls uart_startup which does
>> set_bit(TTY_IO_ERROR, &tty->flags) on the tty. Can't that lead to some
>> issues?
>
> No.
>
>> E.g. we set TTY_IO_ERROR, but since tty is already used by
>> other threads, operations on the tty in other threads will spuriously
>> fail.
>
> See below.
>
>> 195 static int uart_startup(struct tty_struct *tty, struct uart_state *state,
>> 196                 int init_hw)
>> 197 {
>> 198         struct tty_port *port = &state->port;
>> 199         int retval;
>> 200
>> 201         if (port->flags & ASYNC_INITIALIZED)
>> 202                 return 0;
>
> Subsequent opens return success here (note below how the ASYNCB_INITIALIZED bit
> is set in tty->flags if uart_port_startup() returned success from the earlier
> open ?)


Ah, OK, we will mark this data race as intentional then. Thank you.