Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1189914 > unrolled thread
| Started by | Andrey Konovalov <andreyknvl@google.com> |
|---|---|
| First post | 2015-07-22 15:20 +0200 |
| Last post | 2015-07-23 15:40 +0200 |
| Articles | 4 — 3 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
Fwd: Potential data race in psmouse_interrupt Andrey Konovalov <andreyknvl@google.com> - 2015-07-22 15:20 +0200
Re: Fwd: Potential data race in psmouse_interrupt Dmitry Torokhov <dmitry.torokhov@gmail.com> - 2015-07-22 19:00 +0200
Re: Potential data race in psmouse_interrupt Pali Rohár <pali.rohar@gmail.com> - 2015-07-23 15:10 +0200
Re: Potential data race in psmouse_interrupt Andrey Konovalov <andreyknvl@google.com> - 2015-07-23 15:40 +0200
| From | Andrey Konovalov <andreyknvl@google.com> |
|---|---|
| Date | 2015-07-22 15:20 +0200 |
| Subject | Fwd: Potential data race in psmouse_interrupt |
| Message-ID | <pP26e-7TN-29@gated-at.bofh.it> |
Hi!
We are working on a dynamic data race detector for Linux kernel called
KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
Here is a report we got while running ktsan (upstream revision
21bdb584af8cca7c6df3c44cba268be050a234eb).
==================================================================
ThreadSanitizer: data-race in psmouse_interrupt
Write of size 1 by thread T1 (K1):
[<ffffffff819d5272>] psmouse_interrupt+0xd2/0x690
drivers/input/mouse/psmouse-base.c:337
[<ffffffff819bcd16>] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
[<ffffffff819be5f0>] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
[<ffffffff810f03b2>] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
[<ffffffff810f0692>] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
[<ffffffff810f5414>] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
[< inlined >] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
[<ffffffff81009f86>] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
[<ffffffff810093ce>] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
[<ffffffff81e726ab>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
[< inlined >] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
[<ffffffff8108edd8>] irq_exit+0x98/0xa0 kernel/softirq.c:391
[< inlined >] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
./arch/x86/include/asm/apic.h:655
[<ffffffff8105c503>] smp_apic_timer_interrupt+0x63/0x80
arch/x86/kernel/apic/apic.c:915
[<ffffffff81e7299b>] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
[<ffffffff8153223d>] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
[<ffffffff815322be>] kasprintf+0x4e/0x70 lib/kasprintf.c:40
[< inlined >] module_add_driver+0x8f/0x180 make_driver_name
drivers/base/module.c:18
[<ffffffff8183059f>] module_add_driver+0x8f/0x180 drivers/base/module.c:63
[<ffffffff81812c94>] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
[<ffffffff81814e2b>] driver_register+0xdb/0x190 drivers/base/driver.c:168
[<ffffffff81a5ed16>] __hid_register_driver+0xb6/0x100
drivers/hid/hid-core.c:2677
[<ffffffff825ab67d>] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
[<ffffffff81000339>] do_one_initcall+0xb9/0x220 init/main.c:798
[< inlined >] kernel_init_freeable+0x2ca/0x397
do_initcall_level init/main.c:863
[< inlined >] kernel_init_freeable+0x2ca/0x397 do_initcalls
init/main.c:871
[< inlined >] kernel_init_freeable+0x2ca/0x397 do_basic_setup
init/main.c:890
[<ffffffff8253d919>] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
[<ffffffff81e5ad66>] kernel_init+0x16/0x140 init/main.c:941
[<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = ffff88053fd9fe68
DBG: cpu id = 3
Previous read of size 1 by thread T509 (K506):
[< inlined >] cypress_send_ext_cmd+0x193/0x500
cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
[<ffffffff819e6b23>] cypress_send_ext_cmd+0x193/0x500
drivers/input/mouse/cypress_ps2.c:192
[<ffffffff819e6f5a>] cypress_detect+0x2a/0xb0
drivers/input/mouse/cypress_ps2.c:208
[<ffffffff819d5e66>] psmouse_extensions+0x1f6/0x4e0
drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
[<ffffffff819d63fd>] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
[<ffffffff819d7426>] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
[< inlined >] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
[<ffffffff819bcf77>] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
[< inlined >] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
[<ffffffff81813b1a>] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
[<ffffffff81813e64>] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
[<ffffffff81810933>] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
[<ffffffff81813353>] driver_attach+0x33/0x50 drivers/base/dd.c:631
[< inlined >] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
[<ffffffff819bd8e3>] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
[<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
[<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
[<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
[<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0
DBG: addr: ffff88019d703909
DBG: first offset: 1, second offset: 1
DBG: T1 clock: {T1: 17075020, T509: 142163}
DBG: T509 clock: {T509: 142167}
==================================================================
It seems that accessing 'psmouse->pktcnt' in
'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
'cypress_ps2_read_cmd_status()'.
If that's the case, it's possible that 'psmouse->pktcnt' is
incremented, but no data is written yet, so '(psmouse->pktcnt >=
pktsize)' will evaluate to true and the following 'memcpy' will access
invalid data.
Could you confirm if this is a real data race?
Thanks in advance!
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [next] | [standalone]
| From | Dmitry Torokhov <dmitry.torokhov@gmail.com> |
|---|---|
| Date | 2015-07-22 19:00 +0200 |
| Message-ID | <pP5xa-4rv-5@gated-at.bofh.it> |
| In reply to | #1189914 |
On Wed, Jul 22, 2015 at 03:14:42PM +0200, Andrey Konovalov wrote:
> Hi!
>
> We are working on a dynamic data race detector for Linux kernel called
> KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
>
> Here is a report we got while running ktsan (upstream revision
> 21bdb584af8cca7c6df3c44cba268be050a234eb).
>
> ==================================================================
> ThreadSanitizer: data-race in psmouse_interrupt
>
> Write of size 1 by thread T1 (K1):
> [<ffffffff819d5272>] psmouse_interrupt+0xd2/0x690
> drivers/input/mouse/psmouse-base.c:337
> [<ffffffff819bcd16>] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
> [<ffffffff819be5f0>] i8042_interrupt+0x240/0x4d0
> drivers/input/serio/i8042.c:541
> [<ffffffff810f03b2>] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
> [<ffffffff810f0692>] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
> [<ffffffff810f5414>] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
> [< inlined >] handle_irq+0xf6/0x220 generic_handle_irq_desc
> include/linux/irqdesc.h:146
> [<ffffffff81009f86>] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
> [<ffffffff810093ce>] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
> [<ffffffff81e726ab>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
> [< inlined >] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
> [<ffffffff8108edd8>] irq_exit+0x98/0xa0 kernel/softirq.c:391
> [< inlined >] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
> ./arch/x86/include/asm/apic.h:655
> [<ffffffff8105c503>] smp_apic_timer_interrupt+0x63/0x80
> arch/x86/kernel/apic/apic.c:915
> [<ffffffff81e7299b>] apic_timer_interrupt+0x6b/0x70
> arch/x86/entry/entry_64.S:782
> [<ffffffff8153223d>] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
> [<ffffffff815322be>] kasprintf+0x4e/0x70 lib/kasprintf.c:40
> [< inlined >] module_add_driver+0x8f/0x180 make_driver_name
> drivers/base/module.c:18
> [<ffffffff8183059f>] module_add_driver+0x8f/0x180 drivers/base/module.c:63
> [<ffffffff81812c94>] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
> [<ffffffff81814e2b>] driver_register+0xdb/0x190 drivers/base/driver.c:168
> [<ffffffff81a5ed16>] __hid_register_driver+0xb6/0x100
> drivers/hid/hid-core.c:2677
> [<ffffffff825ab67d>] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
> [<ffffffff81000339>] do_one_initcall+0xb9/0x220 init/main.c:798
> [< inlined >] kernel_init_freeable+0x2ca/0x397
> do_initcall_level init/main.c:863
> [< inlined >] kernel_init_freeable+0x2ca/0x397 do_initcalls
> init/main.c:871
> [< inlined >] kernel_init_freeable+0x2ca/0x397 do_basic_setup
> init/main.c:890
> [<ffffffff8253d919>] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
> [<ffffffff81e5ad66>] kernel_init+0x16/0x140 init/main.c:941
> [<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = ffff88053fd9fe68
> DBG: cpu id = 3
>
> Previous read of size 1 by thread T509 (K506):
> [< inlined >] cypress_send_ext_cmd+0x193/0x500
> cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
> [<ffffffff819e6b23>] cypress_send_ext_cmd+0x193/0x500
> drivers/input/mouse/cypress_ps2.c:192
> [<ffffffff819e6f5a>] cypress_detect+0x2a/0xb0
> drivers/input/mouse/cypress_ps2.c:208
> [<ffffffff819d5e66>] psmouse_extensions+0x1f6/0x4e0
> drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
> [<ffffffff819d63fd>] psmouse_switch_protocol+0x2ad/0x330
> drivers/input/mouse/psmouse-base.c:1467
> [<ffffffff819d7426>] psmouse_connect+0x2e6/0x450
> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
> [< inlined >] serio_driver_probe+0x57/0x80
> serio_connect_driver drivers/input/serio/serio.c:65
> [<ffffffff819bcf77>] serio_driver_probe+0x57/0x80
> drivers/input/serio/serio.c:796
> [< inlined >] driver_probe_device+0x1da/0x460 really_probe
> drivers/base/dd.c:308
> [<ffffffff81813b1a>] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
> [<ffffffff81813e64>] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
> [<ffffffff81810933>] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
> [<ffffffff81813353>] driver_attach+0x33/0x50 drivers/base/dd.c:631
> [< inlined >] serio_handle_event+0x2d3/0x3b0
> serio_attach_driver drivers/input/serio/serio.c:826
> [<ffffffff819bd8e3>] serio_handle_event+0x2d3/0x3b0
> drivers/input/serio/serio.c:245
> [<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
> [<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
> [<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
> [<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 0
>
> DBG: addr: ffff88019d703909
> DBG: first offset: 1, second offset: 1
> DBG: T1 clock: {T1: 17075020, T509: 142163}
> DBG: T509 clock: {T509: 142167}
> ==================================================================
>
> It seems that accessing 'psmouse->pktcnt' in
> 'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
> is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
> pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
> 'cypress_ps2_read_cmd_status()'.
> If that's the case, it's possible that 'psmouse->pktcnt' is
> incremented, but no data is written yet, so '(psmouse->pktcnt >=
> pktsize)' will evaluate to true and the following 'memcpy' will access
> invalid data.
>
> Could you confirm if this is a real data race?
Yes, looks like real positive.
Thanks.
--
Dmitry
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Pali Rohár <pali.rohar@gmail.com> |
|---|---|
| Date | 2015-07-23 15:10 +0200 |
| Message-ID | <pPoq8-7Bj-49@gated-at.bofh.it> |
| In reply to | #1189914 |
On Wednesday 22 July 2015 15:14:42 Andrey Konovalov wrote:
> Hi!
>
> We are working on a dynamic data race detector for Linux kernel called
> KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
>
> Here is a report we got while running ktsan (upstream revision
> 21bdb584af8cca7c6df3c44cba268be050a234eb).
>
> ==================================================================
> ThreadSanitizer: data-race in psmouse_interrupt
>
> Write of size 1 by thread T1 (K1):
> [<ffffffff819d5272>] psmouse_interrupt+0xd2/0x690
> drivers/input/mouse/psmouse-base.c:337
> [<ffffffff819bcd16>] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
> [<ffffffff819be5f0>] i8042_interrupt+0x240/0x4d0
> drivers/input/serio/i8042.c:541
> [<ffffffff810f03b2>] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
> [<ffffffff810f0692>] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
> [<ffffffff810f5414>] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
> [< inlined >] handle_irq+0xf6/0x220 generic_handle_irq_desc
> include/linux/irqdesc.h:146
> [<ffffffff81009f86>] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
> [<ffffffff810093ce>] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
> [<ffffffff81e726ab>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
> [< inlined >] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
> [<ffffffff8108edd8>] irq_exit+0x98/0xa0 kernel/softirq.c:391
> [< inlined >] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
> ./arch/x86/include/asm/apic.h:655
> [<ffffffff8105c503>] smp_apic_timer_interrupt+0x63/0x80
> arch/x86/kernel/apic/apic.c:915
> [<ffffffff81e7299b>] apic_timer_interrupt+0x6b/0x70
> arch/x86/entry/entry_64.S:782
> [<ffffffff8153223d>] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
> [<ffffffff815322be>] kasprintf+0x4e/0x70 lib/kasprintf.c:40
> [< inlined >] module_add_driver+0x8f/0x180 make_driver_name
> drivers/base/module.c:18
> [<ffffffff8183059f>] module_add_driver+0x8f/0x180 drivers/base/module.c:63
> [<ffffffff81812c94>] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
> [<ffffffff81814e2b>] driver_register+0xdb/0x190 drivers/base/driver.c:168
> [<ffffffff81a5ed16>] __hid_register_driver+0xb6/0x100
> drivers/hid/hid-core.c:2677
> [<ffffffff825ab67d>] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
> [<ffffffff81000339>] do_one_initcall+0xb9/0x220 init/main.c:798
> [< inlined >] kernel_init_freeable+0x2ca/0x397
> do_initcall_level init/main.c:863
> [< inlined >] kernel_init_freeable+0x2ca/0x397 do_initcalls
> init/main.c:871
> [< inlined >] kernel_init_freeable+0x2ca/0x397 do_basic_setup
> init/main.c:890
> [<ffffffff8253d919>] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
> [<ffffffff81e5ad66>] kernel_init+0x16/0x140 init/main.c:941
> [<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = ffff88053fd9fe68
> DBG: cpu id = 3
>
> Previous read of size 1 by thread T509 (K506):
> [< inlined >] cypress_send_ext_cmd+0x193/0x500
> cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
> [<ffffffff819e6b23>] cypress_send_ext_cmd+0x193/0x500
> drivers/input/mouse/cypress_ps2.c:192
> [<ffffffff819e6f5a>] cypress_detect+0x2a/0xb0
> drivers/input/mouse/cypress_ps2.c:208
> [<ffffffff819d5e66>] psmouse_extensions+0x1f6/0x4e0
> drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
> [<ffffffff819d63fd>] psmouse_switch_protocol+0x2ad/0x330
> drivers/input/mouse/psmouse-base.c:1467
> [<ffffffff819d7426>] psmouse_connect+0x2e6/0x450
> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
> [< inlined >] serio_driver_probe+0x57/0x80
> serio_connect_driver drivers/input/serio/serio.c:65
> [<ffffffff819bcf77>] serio_driver_probe+0x57/0x80
> drivers/input/serio/serio.c:796
> [< inlined >] driver_probe_device+0x1da/0x460 really_probe
> drivers/base/dd.c:308
> [<ffffffff81813b1a>] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
> [<ffffffff81813e64>] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
> [<ffffffff81810933>] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
> [<ffffffff81813353>] driver_attach+0x33/0x50 drivers/base/dd.c:631
> [< inlined >] serio_handle_event+0x2d3/0x3b0
> serio_attach_driver drivers/input/serio/serio.c:826
> [<ffffffff819bd8e3>] serio_handle_event+0x2d3/0x3b0
> drivers/input/serio/serio.c:245
> [<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
> [<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
> [<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
> [<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 0
>
> DBG: addr: ffff88019d703909
> DBG: first offset: 1, second offset: 1
> DBG: T1 clock: {T1: 17075020, T509: 142163}
> DBG: T509 clock: {T509: 142167}
> ==================================================================
>
> It seems that accessing 'psmouse->pktcnt' in
> 'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
> is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
> pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
> 'cypress_ps2_read_cmd_status()'.
> If that's the case, it's possible that 'psmouse->pktcnt' is
> incremented, but no data is written yet, so '(psmouse->pktcnt >=
> pktsize)' will evaluate to true and the following 'memcpy' will access
> invalid data.
>
> Could you confirm if this is a real data race?
>
> Thanks in advance!
>
Hi Andrey,
I would like to ask you, did not you noticed some problem from Sanitizer
with psmouse-base.c and alps.c code?
There is unknown problem when alps.c receive invalid data from
psmouse_interrupt/serio_interrupt/i8042_interrupt.
And when I read your email with race condition & accesing invalid data
in cypress driver. I'm thinking if there cannot be something like that.
--
Pali Rohár
pali.rohar@gmail.com
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Andrey Konovalov <andreyknvl@google.com> |
|---|---|
| Date | 2015-07-23 15:40 +0200 |
| Message-ID | <pPoT9-89c-33@gated-at.bofh.it> |
| In reply to | #1190907 |
Hi Pali,
There are a few reports in psmouse-base.c/alps.c code as well.
Here is a couple of them that are printed one right after another.
The second one tells about a race on ps2dev->cmdcnt.
==================================================================
ThreadSanitizer: data-race in ps2_handle_ack
Write of size 8 by thread T6 (K6):
[<ffffffff819c0b83>] ps2_handle_ack+0xf3/0x180 drivers/input/serio/libps2.c:322
[<ffffffff819d55d7>] psmouse_interrupt+0x207/0x690
drivers/input/mouse/psmouse-base.c:317
[<ffffffff819bcf46>] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
[<ffffffff819be820>] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
[<ffffffff810f03b2>] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
[<ffffffff810f0692>] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
[<ffffffff810f5414>] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
[< inlined >] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
[<ffffffff81009f86>] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
[<ffffffff810093ce>] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
[<ffffffff81e728ab>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
[< inlined >] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
[<ffffffff8108edd8>] irq_exit+0x98/0xa0 kernel/softirq.c:391
[< inlined >] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
./arch/x86/include/asm/apic.h:655
[<ffffffff8105c503>] smp_apic_timer_interrupt+0x63/0x80
arch/x86/kernel/apic/apic.c:915
[<ffffffff81e72b9b>] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
[<ffffffff81086fe3>] _do_fork+0x133/0x500 kernel/fork.c:1719
[<ffffffff810873ec>] kernel_thread+0x3c/0x60 kernel/fork.c:1772
[<ffffffff810a71dc>] __call_usermodehelper+0x5c/0x90 kernel/kmod.c:317
[<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
[<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
[<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
[<ffffffff81e7215f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = ffff88053fd9fe68
DBG: cpu id = 3
Previous read of size 8 by thread T397 (K394):
[<ffffffff819c0cf2>] ps2_sendbyte+0xe2/0x210 drivers/input/serio/libps2.c:45
[<ffffffff819c1109>] __ps2_command+0x159/0x660 drivers/input/serio/libps2.c:214
[<ffffffff819c1645>] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
[<ffffffff819dd412>] alps_rpt_cmd+0x42/0xe0
drivers/input/mouse/alps.c:1665 (discriminator 1)
[<ffffffff819e12b6>] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
[<ffffffff819e3498>] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
[< inlined >] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
drivers/input/mouse/psmouse-base.c:752
[<ffffffff819d60fe>] psmouse_extensions+0x25e/0x4e0
drivers/input/mouse/psmouse-base.c:870
[<ffffffff819d662d>] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
[<ffffffff819d7656>] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
[< inlined >] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
[<ffffffff819bd1a7>] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
[< inlined >] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
[<ffffffff81813d4a>] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
[<ffffffff81814094>] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
[<ffffffff81810b63>] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
[<ffffffff81813583>] driver_attach+0x33/0x50 drivers/base/dd.c:631
[< inlined >] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
[<ffffffff819bdb13>] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
[<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
[<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
[<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
[<ffffffff81e7215f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0
DBG: addr: ffff88019a923a58
DBG: first offset: 0, second offset: 0
DBG: T6 clock: {T6: 2264295, T397: 174118}
DBG: T397 clock: {T397: 174122}
==================================================================
==================================================================
ThreadSanitizer: data-race in __ps2_command
Read of size 1 by thread T397 (K394):
[<ffffffff819c1220>] __ps2_command+0x270/0x660
drivers/input/serio/libps2.c:230 (discriminator 21)
[<ffffffff819c1645>] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
[<ffffffff819dd47e>] alps_rpt_cmd+0xae/0xe0 drivers/input/mouse/alps.c:1674
[<ffffffff819e12b6>] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
[<ffffffff819e3498>] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
[< inlined >] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
drivers/input/mouse/psmouse-base.c:752
[<ffffffff819d60fe>] psmouse_extensions+0x25e/0x4e0
drivers/input/mouse/psmouse-base.c:870
[<ffffffff819d662d>] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
[<ffffffff819d7656>] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
[< inlined >] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
[<ffffffff819bd1a7>] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
[< inlined >] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
[<ffffffff81813d4a>] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
[<ffffffff81814094>] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
[<ffffffff81810b63>] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
[<ffffffff81813583>] driver_attach+0x33/0x50 drivers/base/dd.c:631
[< inlined >] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
[<ffffffff819bdb13>] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
[<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
[<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
[<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
[<ffffffff81e7215f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = ffff88053fc9fe68
DBG: cpu id = 1
Previous write of size 1 by thread T6 (K6):
[<ffffffff819c09a6>] ps2_handle_response+0x46/0x130
drivers/input/serio/libps2.c:346
[<ffffffff819d58a4>] psmouse_interrupt+0x4d4/0x690
drivers/input/mouse/psmouse-base.c:321
[<ffffffff819bcf46>] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
[<ffffffff819be820>] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
[<ffffffff810f03b2>] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
[<ffffffff810f0692>] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
[<ffffffff810f5414>] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
[< inlined >] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
[<ffffffff81009f86>] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
[<ffffffff810093ce>] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
[<ffffffff81e728ab>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
[<ffffffff81e72b9b>] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
[< inlined >] kvm_clock_get_cycles+0x3e/0x50 kvm_clock_read
arch/x86/kernel/kvmclock.c:85
[<ffffffff8106e74e>] kvm_clock_get_cycles+0x3e/0x50
arch/x86/kernel/kvmclock.c:92
[< inlined >] ktime_get_with_offset+0x99/0x180
timekeeping_get_delta kernel/time/timekeeping.c:210
[< inlined >] ktime_get_with_offset+0x99/0x180
timekeeping_get_ns kernel/time/timekeeping.c:306
[<ffffffff81114da9>] ktime_get_with_offset+0x99/0x180
kernel/time/timekeeping.c:720
[< inlined >] copy_process.part.44+0x773/0x2c40
ktime_get_boottime include/linux/timekeeping.h:183
[< inlined >] copy_process.part.44+0x773/0x2c40
ktime_get_boot_ns include/linux/timekeeping.h:214
[<ffffffff810848b3>] copy_process.part.44+0x773/0x2c40 kernel/fork.c:1363
[< inlined >] _do_fork+0x103/0x500 copy_process kernel/fork.c:1261
[<ffffffff81086fb3>] _do_fork+0x103/0x500 kernel/fork.c:1709
[<ffffffff810873ec>] kernel_thread+0x3c/0x60 kernel/fork.c:1772
[<ffffffff810a71dc>] __call_usermodehelper+0x5c/0x90 kernel/kmod.c:317
[<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
[<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
[<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
[<ffffffff81e7215f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0
DBG: addr: ffff88019a923a68
DBG: first offset: 0, second offset: 0
DBG: T397 clock: {T397: 175738, T6: 2266233}
DBG: T6 clock: {T6: 2266336}
==================================================================
On Thu, Jul 23, 2015 at 3:08 PM, Pali Rohár <pali.rohar@gmail.com> wrote:
> On Wednesday 22 July 2015 15:14:42 Andrey Konovalov wrote:
>> Hi!
>>
>> We are working on a dynamic data race detector for Linux kernel called
>> KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
>>
>> Here is a report we got while running ktsan (upstream revision
>> 21bdb584af8cca7c6df3c44cba268be050a234eb).
>>
>> ==================================================================
>> ThreadSanitizer: data-race in psmouse_interrupt
>>
>> Write of size 1 by thread T1 (K1):
>> [<ffffffff819d5272>] psmouse_interrupt+0xd2/0x690
>> drivers/input/mouse/psmouse-base.c:337
>> [<ffffffff819bcd16>] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
>> [<ffffffff819be5f0>] i8042_interrupt+0x240/0x4d0
>> drivers/input/serio/i8042.c:541
>> [<ffffffff810f03b2>] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
>> [<ffffffff810f0692>] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
>> [<ffffffff810f5414>] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
>> [< inlined >] handle_irq+0xf6/0x220 generic_handle_irq_desc
>> include/linux/irqdesc.h:146
>> [<ffffffff81009f86>] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
>> [<ffffffff810093ce>] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
>> [<ffffffff81e726ab>] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
>> [< inlined >] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
>> [<ffffffff8108edd8>] irq_exit+0x98/0xa0 kernel/softirq.c:391
>> [< inlined >] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
>> ./arch/x86/include/asm/apic.h:655
>> [<ffffffff8105c503>] smp_apic_timer_interrupt+0x63/0x80
>> arch/x86/kernel/apic/apic.c:915
>> [<ffffffff81e7299b>] apic_timer_interrupt+0x6b/0x70
>> arch/x86/entry/entry_64.S:782
>> [<ffffffff8153223d>] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
>> [<ffffffff815322be>] kasprintf+0x4e/0x70 lib/kasprintf.c:40
>> [< inlined >] module_add_driver+0x8f/0x180 make_driver_name
>> drivers/base/module.c:18
>> [<ffffffff8183059f>] module_add_driver+0x8f/0x180 drivers/base/module.c:63
>> [<ffffffff81812c94>] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
>> [<ffffffff81814e2b>] driver_register+0xdb/0x190 drivers/base/driver.c:168
>> [<ffffffff81a5ed16>] __hid_register_driver+0xb6/0x100
>> drivers/hid/hid-core.c:2677
>> [<ffffffff825ab67d>] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
>> [<ffffffff81000339>] do_one_initcall+0xb9/0x220 init/main.c:798
>> [< inlined >] kernel_init_freeable+0x2ca/0x397
>> do_initcall_level init/main.c:863
>> [< inlined >] kernel_init_freeable+0x2ca/0x397 do_initcalls
>> init/main.c:871
>> [< inlined >] kernel_init_freeable+0x2ca/0x397 do_basic_setup
>> init/main.c:890
>> [<ffffffff8253d919>] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
>> [<ffffffff81e5ad66>] kernel_init+0x16/0x140 init/main.c:941
>> [<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
>> DBG: cpu = ffff88053fd9fe68
>> DBG: cpu id = 3
>>
>> Previous read of size 1 by thread T509 (K506):
>> [< inlined >] cypress_send_ext_cmd+0x193/0x500
>> cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
>> [<ffffffff819e6b23>] cypress_send_ext_cmd+0x193/0x500
>> drivers/input/mouse/cypress_ps2.c:192
>> [<ffffffff819e6f5a>] cypress_detect+0x2a/0xb0
>> drivers/input/mouse/cypress_ps2.c:208
>> [<ffffffff819d5e66>] psmouse_extensions+0x1f6/0x4e0
>> drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
>> [<ffffffff819d63fd>] psmouse_switch_protocol+0x2ad/0x330
>> drivers/input/mouse/psmouse-base.c:1467
>> [<ffffffff819d7426>] psmouse_connect+0x2e6/0x450
>> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
>> [< inlined >] serio_driver_probe+0x57/0x80
>> serio_connect_driver drivers/input/serio/serio.c:65
>> [<ffffffff819bcf77>] serio_driver_probe+0x57/0x80
>> drivers/input/serio/serio.c:796
>> [< inlined >] driver_probe_device+0x1da/0x460 really_probe
>> drivers/base/dd.c:308
>> [<ffffffff81813b1a>] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
>> [<ffffffff81813e64>] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
>> [<ffffffff81810933>] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
>> [<ffffffff81813353>] driver_attach+0x33/0x50 drivers/base/dd.c:631
>> [< inlined >] serio_handle_event+0x2d3/0x3b0
>> serio_attach_driver drivers/input/serio/serio.c:826
>> [<ffffffff819bd8e3>] serio_handle_event+0x2d3/0x3b0
>> drivers/input/serio/serio.c:245
>> [<ffffffff810adcf9>] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
>> [<ffffffff810aeddf>] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
>> [<ffffffff810b700c>] kthread+0x15c/0x180 kernel/kthread.c:207
>> [<ffffffff81e71f5f>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
>> DBG: cpu = 0
>>
>> DBG: addr: ffff88019d703909
>> DBG: first offset: 1, second offset: 1
>> DBG: T1 clock: {T1: 17075020, T509: 142163}
>> DBG: T509 clock: {T509: 142167}
>> ==================================================================
>>
>> It seems that accessing 'psmouse->pktcnt' in
>> 'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
>> is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
>> pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
>> 'cypress_ps2_read_cmd_status()'.
>> If that's the case, it's possible that 'psmouse->pktcnt' is
>> incremented, but no data is written yet, so '(psmouse->pktcnt >=
>> pktsize)' will evaluate to true and the following 'memcpy' will access
>> invalid data.
>>
>> Could you confirm if this is a real data race?
>>
>> Thanks in advance!
>>
>
> Hi Andrey,
>
> I would like to ask you, did not you noticed some problem from Sanitizer
> with psmouse-base.c and alps.c code?
>
> There is unknown problem when alps.c receive invalid data from
> psmouse_interrupt/serio_interrupt/i8042_interrupt.
>
> And when I read your email with race condition & accesing invalid data
> in cypress driver. I'm thinking if there cannot be something like that.
>
> --
> Pali Rohár
> pali.rohar@gmail.com
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web