* BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
@ 2022-02-07 16:14 Paul Menzel
2022-02-07 18:42 ` Jason A. Donenfeld
0 siblings, 1 reply; 15+ messages in thread
From: Paul Menzel @ 2022-02-07 16:14 UTC (permalink / raw)
To: Theodore Y. Ts'o, Jason A. Donenfeld; +Cc: LKML
[-- Attachment #1: Type: text/plain, Size: 1577 bytes --]
Dear Linux folks,
Running Linux 5.17-rc2+ in QEMU 6.2.0 the Kernel Concurrency Sanitizer
reports the race below:
qemu-system-x86_64 -cpu host -smp cpus=3 -m 2G -enable-kvm -usb
-device usb-host,vendorid=0x8087,productid=0x0a2a -drive
file=/dev/shm/debian-64.img,format=raw,if=virtio -net nic -net
user,hostfwd=tcp::22223-:22 -kernel /dev/shm/bzImage -append
"root=/dev/vda1 rw quiet"
```
[ 3.383861]
==================================================================
[ 3.385662] BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
[ 3.387142]
[ 3.387905] race at unknown origin, with read to 0xffff9ec881ad3008
of 1 bytes by task 44 on cpu 0:
[ 3.389778] add_device_randomness+0x20d/0x290
[ 3.389789] release_task+0x231/0xb20
[ 3.389800] wait_consider_task+0x883/0x17d0
[ 3.389809] do_wait+0x2b4/0x4d0
[ 3.389818] kernel_wait+0x71/0xd0
[ 3.389827] call_usermodehelper_exec_work+0xa3/0xb0
[ 3.389838] process_one_work+0x477/0x7d0
[ 3.389845] worker_thread+0x2ec/0x810
[ 3.389851] kthread+0x16d/0x1a0
[ 3.389860] ret_from_fork+0x22/0x30
[ 3.389868]
[ 3.390623] value changed: 0x00 -> 0x43
[ 3.391594]
[ 3.392363] Reported by Kernel Concurrency Sanitizer on:
[ 3.394131] CPU: 0 PID: 44 Comm: kworker/u6:2 Not tainted
5.17.0-rc2-00353-g90c9e950c0de #34
[ 3.394151] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.15.0-1 04/01/2014
[ 3.394190] Workqueue: events_unbound call_usermodehelper_exec_work
```
Please find the output of `dmesg` attached.
Kind regards,
Paul
[-- Attachment #2: linux-5.17-rc2-kcsan-add_device_randomness.txt --]
[-- Type: text/plain, Size: 29356 bytes --]
[ 0.000000] Linux version 5.17.0-rc2-00353-g90c9e950c0de (pmenzel@invidia.molgen.mpg.de) (gcc (GCC) 11.1.0, GNU ld (GNU Binutils) 2.37) #34 SMP PREEMPT Sun Feb 6 13:11:13 CET 2022
[ 0.000000] Command line: root=/dev/vda1 rw quiet
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[ 0.000000] signal: max sigframe size: 1776
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffdafff] usable
[ 0.000000] BIOS-e820: [mem 0x000000007ffdb000-0x000000007fffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.8 present.
[ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.15.0-1 04/01/2014
[ 0.000000] tsc: Fast TSC calibration using PIT
[ 0.000000] tsc: Detected 2594.129 MHz processor
[ 0.003433] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.003448] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.003461] last_pfn = 0x7ffdb max_arch_pfn = 0x400000000
[ 0.003590] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
[ 0.011783] found SMP MP-table at [mem 0x000f5b90-0x000f5b9f]
[ 0.012404] Using GB pages for direct mapping
[ 0.013195] ACPI: Early table checksum verification disabled
[ 0.013342] ACPI: RSDP 0x00000000000F59D0 000014 (v00 BOCHS )
[ 0.013378] ACPI: RSDT 0x000000007FFE19C5 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001)
[ 0.013431] ACPI: FACP 0x000000007FFE1869 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001)
[ 0.013452] ACPI: DSDT 0x000000007FFE0040 001829 (v01 BOCHS BXPC 00000001 BXPC 00000001)
[ 0.013476] ACPI: FACS 0x000000007FFE0000 000040
[ 0.013489] ACPI: APIC 0x000000007FFE18DD 000088 (v01 BOCHS BXPC 00000001 BXPC 00000001)
[ 0.013506] ACPI: HPET 0x000000007FFE1965 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001)
[ 0.013523] ACPI: WAET 0x000000007FFE199D 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001)
[ 0.013538] ACPI: Reserving FACP table memory at [mem 0x7ffe1869-0x7ffe18dc]
[ 0.013545] ACPI: Reserving DSDT table memory at [mem 0x7ffe0040-0x7ffe1868]
[ 0.013551] ACPI: Reserving FACS table memory at [mem 0x7ffe0000-0x7ffe003f]
[ 0.013557] ACPI: Reserving APIC table memory at [mem 0x7ffe18dd-0x7ffe1964]
[ 0.013564] ACPI: Reserving HPET table memory at [mem 0x7ffe1965-0x7ffe199c]
[ 0.013570] ACPI: Reserving WAET table memory at [mem 0x7ffe199d-0x7ffe19c4]
[ 0.013824] ACPI: CEDT not present
[ 0.014520] No NUMA configuration found
[ 0.014525] Faking a node at [mem 0x0000000000000000-0x000000007ffdafff]
[ 0.014543] NODE_DATA(0) allocated [mem 0x7ffd7000-0x7ffdafff]
[ 0.014659] Zone ranges:
[ 0.014663] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.014671] DMA32 [mem 0x0000000001000000-0x000000007ffdafff]
[ 0.014679] Normal empty
[ 0.014684] Movable zone start for each node
[ 0.014688] Early memory node ranges
[ 0.014691] node 0: [mem 0x0000000000001000-0x000000000009efff]
[ 0.014704] node 0: [mem 0x0000000000100000-0x000000007ffdafff]
[ 0.014718] Initmem setup node 0 [mem 0x0000000000001000-0x000000007ffdafff]
[ 0.015085] On node 0, zone DMA: 1 pages in unavailable ranges
[ 0.015106] On node 0, zone DMA: 97 pages in unavailable ranges
[ 0.021342] On node 0, zone DMA32: 37 pages in unavailable ranges
[ 0.022310] ACPI: PM-Timer IO Port: 0x608
[ 0.022345] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[ 0.022460] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[ 0.022470] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.022478] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[ 0.022484] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.022499] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[ 0.022506] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[ 0.022527] ACPI: Using ACPI (MADT) for SMP configuration information
[ 0.022532] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[ 0.022555] TSC deadline timer available
[ 0.022581] smpboot: Allowing 3 CPUs, 0 hotplug CPUs
[ 0.022711] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[ 0.022720] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[ 0.022725] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff]
[ 0.022731] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[ 0.022739] [mem 0x80000000-0xfeffbfff] available for PCI devices
[ 0.022797] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[ 0.031445] setup_percpu: NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:3 nr_node_ids:1
[ 0.032130] percpu: Embedded 53 pages/cpu s176984 r8192 d31912 u524288
[ 0.032163] pcpu-alloc: s176984 r8192 d31912 u524288 alloc=1*2097152
[ 0.032174] pcpu-alloc: [0] 0 1 2 -
[ 0.032306] Fallback order for Node 0: 0
[ 0.032322] Built 1 zonelists, mobility grouping on. Total pages: 515803
[ 0.032328] Policy zone: DMA32
[ 0.032345] Kernel command line: root=/dev/vda1 rw quiet
[ 0.032866] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[ 0.032960] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[ 0.033130] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.038062] Memory: 2014056K/2096612K available (24588K kernel code, 2637K rwdata, 5136K rodata, 1444K init, 1372K bss, 82296K reserved, 0K cma-reserved)
[ 0.038245] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=3, Nodes=1
[ 0.038294] Kernel/User page tables isolation: enabled
[ 0.047061] Dynamic Preempt: voluntary
[ 0.047626] rcu: Preemptible hierarchical RCU implementation.
[ 0.047632] rcu: RCU event tracing is enabled.
[ 0.047641] rcu: RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=3.
[ 0.047648] Trampoline variant of Tasks RCU enabled.
[ 0.047651] Rude variant of Tasks RCU enabled.
[ 0.047654] Tracing variant of Tasks RCU enabled.
[ 0.047676] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
[ 0.047681] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=3
[ 0.053333] NR_IRQS: 4352, nr_irqs: 448, preallocated irqs: 16
[ 0.053966] random: get_random_bytes called from start_kernel+0x57c/0x82a with crng_init=0
[ 0.074045] Console: colour VGA+ 80x25
[ 0.074157] printk: console [tty0] enabled
[ 0.074225] ACPI: Core revision 20211217
[ 0.074732] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[ 0.075136] APIC: Switch to symmetric I/O mode setup
[ 0.080564] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.085050] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x2564922aed9, max_idle_ns: 440795297334 ns
[ 0.085100] Calibrating delay loop (skipped), value calculated using timer frequency.. 5188.25 BogoMIPS (lpj=2594129)
[ 0.085118] pid_max: default: 32768 minimum: 301
[ 0.085178] LSM: Security Framework initializing
[ 0.085208] SELinux: Initializing.
[ 0.085269] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[ 0.085279] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
[ 0.087295] x86/cpu: User Mode Instruction Prevention (UMIP) activated
[ 0.088357] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[ 0.088371] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[ 0.088500] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[ 0.088513] Spectre V2 : Mitigation: Full generic retpoline
[ 0.088517] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[ 0.088527] Spectre V2 : Enabling Restricted Speculation for firmware calls
[ 0.088545] Spectre V2 : mitigation: Enabling conditional Indirect Branch Prediction Barrier
[ 0.088551] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl
[ 0.088569] TAA: Mitigation: Clear CPU buffers
[ 0.088575] SRBDS: Unknown: Dependent on hypervisor status
[ 0.088579] MDS: Mitigation: Clear CPU buffers
[ 0.110391] Freeing SMP alternatives memory: 44K
[ 0.110801] kcsan: enabled early
[ 0.110809] kcsan: non-strict mode configured - use CONFIG_KCSAN_STRICT=y to see all data races
[ 0.111554] smpboot: CPU0: Intel(R) Core(TM) i7-5600U CPU @ 2.60GHz (family: 0x6, model: 0x3d, stepping: 0x4)
[ 0.111938] cblist_init_generic: Setting adjustable number of callback queues.
[ 0.111945] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.111980] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.112028] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 0.112083] Performance Events: Broadwell events, full-width counters, Intel PMU driver.
[ 0.112083] ... version: 2
[ 0.112083] ... bit width: 48
[ 0.112083] ... generic registers: 4
[ 0.112083] ... value mask: 0000ffffffffffff
[ 0.112083] ... max period: 00007fffffffffff
[ 0.112083] ... fixed-purpose events: 3
[ 0.112083] ... event mask: 000000070000000f
[ 0.112141] rcu: Hierarchical SRCU implementation.
[ 0.114271] smp: Bringing up secondary CPUs ...
[ 0.114865] x86: Booting SMP configuration:
[ 0.114870] .... node #0, CPUs: #1 #2
[ 0.120348] smp: Brought up 1 node, 3 CPUs
[ 0.120362] smpboot: Max logical packages: 1
[ 0.120369] smpboot: Total of 3 processors activated (15564.77 BogoMIPS)
[ 0.122093] devtmpfs: initialized
[ 0.125242] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[ 0.125336] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[ 0.126097] PM: RTC time: 13:12:01, date: 2022-02-06
[ 0.126900] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[ 0.127844] audit: initializing netlink subsys (disabled)
[ 0.128170] audit: type=2000 audit(1644153121.049:1): state=initialized audit_enabled=0 res=1
[ 0.129169] thermal_sys: Registered thermal governor 'step_wise'
[ 0.129174] thermal_sys: Registered thermal governor 'user_space'
[ 0.129318] cpuidle: using governor menu
[ 0.130235] PCI: Using configuration type 1 for base access
[ 0.169366] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
[ 0.170261] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[ 0.171294] ACPI: Added _OSI(Module Device)
[ 0.171302] ACPI: Added _OSI(Processor Device)
[ 0.171307] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.171312] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.171318] ACPI: Added _OSI(Linux-Dell-Video)
[ 0.171323] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[ 0.171329] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[ 0.178852] ACPI: 1 ACPI AML tables successfully acquired and loaded
[ 0.183836] ACPI: Interpreter enabled
[ 0.184030] ACPI: PM: (supports S0 S3 S4 S5)
[ 0.184035] ACPI: Using IOAPIC for interrupt routing
[ 0.184075] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[ 0.184743] ACPI: Enabled 2 GPEs in block 00 to 0F
[ 0.205575] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.205681] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3]
[ 0.205698] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI]
[ 0.205804] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[ 0.206096] PCI host bridge to bus 0000:00
[ 0.206103] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
[ 0.206118] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
[ 0.206132] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[ 0.206147] pci_bus 0000:00: root bus resource [mem 0x80000000-0xfebfffff window]
[ 0.206175] pci_bus 0000:00: root bus resource [mem 0x100000000-0x17fffffff window]
[ 0.206188] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.206316] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[ 0.210561] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[ 0.212596] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180
[ 0.216091] pci 0000:00:01.1: reg 0x20: [io 0xc0e0-0xc0ef]
[ 0.219030] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
[ 0.219101] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
[ 0.219191] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
[ 0.219200] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
[ 0.219857] pci 0000:00:01.2: [8086:7020] type 00 class 0x0c0300
[ 0.222329] pci 0000:00:01.2: reg 0x20: [io 0xc0c0-0xc0df]
[ 0.224729] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[ 0.226100] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
[ 0.226199] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
[ 0.226921] pci 0000:00:02.0: [1234:1111] type 00 class 0x030000
[ 0.228239] pci 0000:00:02.0: reg 0x10: [mem 0xfd000000-0xfdffffff pref]
[ 0.231895] pci 0000:00:02.0: reg 0x18: [mem 0xfebf0000-0xfebf0fff]
[ 0.236777] pci 0000:00:02.0: reg 0x30: [mem 0xfebe0000-0xfebeffff pref]
[ 0.237215] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[ 0.241559] pci 0000:00:03.0: [8086:100e] type 00 class 0x020000
[ 0.242582] pci 0000:00:03.0: reg 0x10: [mem 0xfebc0000-0xfebdffff]
[ 0.243090] pci 0000:00:03.0: reg 0x14: [io 0xc080-0xc0bf]
[ 0.248801] pci 0000:00:03.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref]
[ 0.253079] pci 0000:00:04.0: [1af4:1001] type 00 class 0x010000
[ 0.254091] pci 0000:00:04.0: reg 0x10: [io 0xc000-0xc07f]
[ 0.255091] pci 0000:00:04.0: reg 0x14: [mem 0xfebf1000-0xfebf1fff]
[ 0.259092] pci 0000:00:04.0: reg 0x20: [mem 0xfe000000-0xfe003fff 64bit pref]
[ 0.268797] ACPI: PCI: Interrupt link LNKA configured for IRQ 10
[ 0.269532] ACPI: PCI: Interrupt link LNKB configured for IRQ 10
[ 0.270172] ACPI: PCI: Interrupt link LNKC configured for IRQ 11
[ 0.270837] ACPI: PCI: Interrupt link LNKD configured for IRQ 11
[ 0.271114] ACPI: PCI: Interrupt link LNKS configured for IRQ 9
[ 0.272866] iommu: Default domain type: Translated
[ 0.272872] iommu: DMA domain TLB invalidation policy: lazy mode
[ 0.273152] pci 0000:00:02.0: vgaarb: setting as boot VGA device
[ 0.273160] pci 0000:00:02.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[ 0.273180] pci 0000:00:02.0: vgaarb: bridge control possible
[ 0.273185] vgaarb: loaded
[ 0.274247] SCSI subsystem initialized
[ 0.274422] libata version 3.00 loaded.
[ 0.275236] ACPI: bus type USB registered
[ 0.275329] usbcore: registered new interface driver usbfs
[ 0.275370] usbcore: registered new interface driver hub
[ 0.275471] usbcore: registered new device driver usb
[ 0.275630] pps_core: LinuxPPS API ver. 1 registered
[ 0.275634] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[ 0.275645] PTP clock support registered
[ 0.276262] Advanced Linux Sound Architecture Driver Initialized.
[ 0.277600] Bluetooth: Core ver 2.22
[ 0.277656] NET: Registered PF_BLUETOOTH protocol family
[ 0.277664] Bluetooth: HCI device and connection manager initialized
[ 0.277697] Bluetooth: HCI socket layer initialized
[ 0.277707] Bluetooth: L2CAP socket layer initialized
[ 0.277814] Bluetooth: SCO socket layer initialized
[ 0.277908] NetLabel: Initializing
[ 0.277913] NetLabel: domain hash size = 128
[ 0.277920] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO
[ 0.278067] NetLabel: unlabeled traffic allowed by default
[ 0.278260] PCI: Using ACPI for IRQ routing
[ 0.278260] PCI: pci_cache_line_size set to 64 bytes
[ 0.279113] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[ 0.279142] e820: reserve RAM buffer [mem 0x7ffdb000-0x7fffffff]
[ 0.279516] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[ 0.279536] hpet0: 3 comparators, 64-bit 100.000000 MHz counter
[ 0.282436] clocksource: Switched to clocksource tsc-early
[ 0.365535] VFS: Disk quotas dquot_6.6.0
[ 0.365680] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 0.366032] pnp: PnP ACPI init
[ 0.366739] pnp 00:02: [dma 2]
[ 0.368453] pnp: PnP ACPI: found 6 devices
[ 0.399631] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[ 0.399869] NET: Registered PF_INET protocol family
[ 0.400554] IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear)
[ 0.405875] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes, linear)
[ 0.406014] TCP established hash table entries: 16384 (order: 5, 131072 bytes, linear)
[ 0.407199] TCP bind hash table entries: 16384 (order: 6, 262144 bytes, linear)
[ 0.408812] TCP: Hash tables configured (established 16384 bind 16384)
[ 0.408912] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
[ 0.409292] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
[ 0.409938] NET: Registered PF_UNIX/PF_LOCAL protocol family
[ 0.411035] RPC: Registered named UNIX socket transport module.
[ 0.411045] RPC: Registered udp transport module.
[ 0.411052] RPC: Registered tcp transport module.
[ 0.411058] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.415549] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window]
[ 0.415564] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window]
[ 0.415572] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[ 0.415638] pci_bus 0000:00: resource 7 [mem 0x80000000-0xfebfffff window]
[ 0.415647] pci_bus 0000:00: resource 8 [mem 0x100000000-0x17fffffff window]
[ 0.415836] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[ 0.415879] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.415981] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.605800] ACPI: \_SB_.LNKD: Enabled at IRQ 11
[ 0.798574] pci 0000:00:01.2: quirk_usb_early_handoff+0x0/0x7e0 took 373464 usecs
[ 0.798853] PCI: CLS 0 bytes, default 64
[ 2.154404] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer
[ 2.157955] rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=60 verbose=1 test_no_idle_hz=1 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 stall_cpu=0 stall_cpu_holdoff=10 stall_cpu_irqsoff=0 stall_cpu_block=0 n_barrier_cbs=0 onoff_interval=0 onoff_holdoff=0 read_exit_delay=13 read_exit_burst=16 nocbs_nthreads=0 nocbs_toggle=1000
[ 2.164973] rcu: Start-test grace-period state: g-1131 f0x0
[ 2.166214] rcu_torture_write_types: Testing conditional GPs.
[ 2.166219] rcu_torture_write_types: Testing expedited GPs.
[ 2.166223] rcu_torture_write_types: Testing asynchronous GPs.
[ 2.166272] rcu_torture_write_types: Testing polling GPs.
[ 2.166275] rcu_torture_write_types: Testing normal GPs.
[ 2.166279] rcu-torture: Creating rcu_torture_writer task
[ 2.167930] rcu-torture: Creating rcu_torture_fakewriter task
[ 2.167990] rcu-torture: rcu_torture_writer task started
[ 2.170325] rcu-torture: Creating rcu_torture_fakewriter task
[ 2.170394] rcu-torture: rcu_torture_fakewriter task started
[ 2.171166] rcu-torture: GP expediting controlled from boot/sysfs for rcu.
[ 2.172649] rcu-torture: Creating rcu_torture_fakewriter task
[ 2.172733] rcu-torture: rcu_torture_fakewriter task started
[ 2.181442] rcu-torture: Creating rcu_torture_fakewriter task
[ 2.181476] rcu-torture: rcu_torture_fakewriter task started
[ 2.184189] rcu-torture: Creating rcu_torture_reader task
[ 2.184301] rcu-torture: rcu_torture_fakewriter task started
[ 2.188406] rcu-torture: Creating rcu_torture_reader task
[ 2.188474] rcu-torture: rcu_torture_reader task started
[ 2.189719] rcu-torture: Creating rcu_torture_stats task
[ 2.192289] rcu-torture: rcu_torture_reader task started
[ 2.194059] rcu-torture: Creating torture_shuffle task
[ 2.194081] rcu-torture: rcu_torture_stats task started
[ 2.195951] rcu-torture: Creating torture_stutter task
[ 2.199653] rcu-torture: torture_shuffle task started
[ 2.201023] rcu-torture: Creating rcu_torture_fwd_prog task
[ 2.202815] rcu-torture: torture_stutter task started
[ 2.203981] rcu-torture: Creating rcu_torture_read_exit task
[ 2.204048] rcu-torture: rcu_torture_fwd_progress task started
[ 2.205613] torture_init_begin: Refusing rcu init: rcu running.
[ 2.205645] rcu-torture: rcu_torture_read_exit: Start of test
[ 2.206004] rcu_torture_rea (57) used greatest stack depth: 15448 bytes left
[ 2.210183] torture_init_begin: One torture test at a time!
[ 2.212886] torture_init_begin: Refusing rcu init: rcu running.
[ 2.214362] torture_init_begin: One torture test at a time!
[ 2.217411] Initialise system trusted keyrings
[ 2.217913] workingset: timestamp_bits=56 max_order=19 bucket_order=0
[ 2.237912] NFS: Registering the id_resolver key type
[ 2.238007] Key type id_resolver registered
[ 2.238011] Key type id_legacy registered
[ 2.251394] Key type asymmetric registered
[ 2.251415] Asymmetric key parser 'x509' registered
[ 2.251464] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[ 2.251483] io scheduler mq-deadline registered
[ 2.251488] io scheduler kyber registered
[ 2.252208] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[ 2.252351] ACPI: button: Power Button [PWRF]
[ 2.337913] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 2.338424] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[ 2.341336] Non-volatile memory driver v1.3
[ 2.341635] Linux agpgart interface v0.103
[ 2.341869] ACPI: bus type drm_connector registered
[ 2.356262] loop: module loaded
[ 2.359764] virtio_blk virtio0: [vda] 6291456 512-byte logical blocks (3.22 GB/3.00 GiB)
[ 2.364638] vda: vda1
[ 2.366325] ata_piix 0000:00:01.1: version 2.13
[ 2.369658] scsi host0: ata_piix
[ 2.371316] scsi host1: ata_piix
[ 2.371746] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0e0 irq 14
[ 2.371754] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0e8 irq 15
[ 2.374438] e100: Intel(R) PRO/100 Network Driver
[ 2.374514] e100: Copyright(c) 1999-2006 Intel Corporation
[ 2.374598] e1000: Intel(R) PRO/1000 Network Driver
[ 2.374602] e1000: Copyright (c) 1999-2006 Intel Corporation.
[ 2.528873] ata2: found unknown device (class 0)
[ 2.531061] ata2.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[ 2.533947] scsi 1:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.5+ PQ: 0 ANSI: 5
[ 2.553881] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[ 2.554011] cdrom: Uniform CD-ROM driver Revision: 3.20
[ 2.568640] ACPI: \_SB_.LNKC: Enabled at IRQ 10
[ 2.575892] sr 1:0:0:0: Attached scsi CD-ROM sr0
[ 2.577305] sr 1:0:0:0: Attached scsi generic sg0 type 5
[ 3.021850] e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 52:54:00:12:34:56
[ 3.021887] e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
[ 3.022021] e1000e: Intel(R) PRO/1000 Network Driver
[ 3.022026] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[ 3.022181] sky2: driver version 1.30
[ 3.022999] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 3.023005] ehci-pci: EHCI PCI platform driver
[ 3.023077] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[ 3.023173] ohci-pci: OHCI PCI platform driver
[ 3.023217] uhci_hcd: USB Universal Host Controller Interface driver
[ 3.183364] tsc: Refined TSC clocksource calibration: 2594.012 MHz
[ 3.183416] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x25642392230, max_idle_ns: 440795313887 ns
[ 3.183733] clocksource: Switched to clocksource tsc
[ 3.217532] uhci_hcd 0000:00:01.2: UHCI Host Controller
[ 3.218050] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1
[ 3.218569] uhci_hcd 0000:00:01.2: irq 11, io port 0x0000c0c0
[ 3.218956] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 5.17
[ 3.218967] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 3.218981] usb usb1: Product: UHCI Host Controller
[ 3.218988] usb usb1: Manufacturer: Linux 5.17.0-rc2-00353-g90c9e950c0de uhci_hcd
[ 3.218994] usb usb1: SerialNumber: 0000:00:01.2
[ 3.220022] hub 1-0:1.0: USB hub found
[ 3.220037] hub 1-0:1.0: 2 ports detected
[ 3.221018] usbcore: registered new interface driver usblp
[ 3.221266] usbcore: registered new interface driver usb-storage
[ 3.221514] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[ 3.223996] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 3.224024] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 3.225916] rtc_cmos 00:05: RTC can wake from S4
[ 3.228962] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[ 3.230457] rtc_cmos 00:05: registered as rtc0
[ 3.230643] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs
[ 3.231578] device-mapper: ioctl: 4.45.0-ioctl (2021-03-22) initialised: dm-devel@redhat.com
[ 3.231609] Bluetooth: HCI UART driver ver 2.3
[ 3.231677] Bluetooth: HCI UART protocol H4 registered
[ 3.231791] usbcore: registered new interface driver btusb
[ 3.231803] intel_pstate: CPU model not supported
[ 3.232232] hid: raw HID events driver (C) Jiri Kosina
[ 3.233949] usbcore: registered new interface driver usbhid
[ 3.233960] usbhid: USB HID core driver
[ 3.238590] Initializing XFRM netlink socket
[ 3.239440] NET: Registered PF_INET6 protocol family
[ 3.242784] Segment Routing with IPv6
[ 3.242832] In-situ OAM (IOAM) with IPv6
[ 3.243394] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[ 3.244690] NET: Registered PF_PACKET protocol family
[ 3.245209] Bluetooth: RFCOMM socket layer initialized
[ 3.245280] Bluetooth: RFCOMM ver 1.11
[ 3.245425] Key type dns_resolver registered
[ 3.247507] IPI shorthand broadcast: enabled
[ 3.247618] sched_clock: Marking stable (3221817538, 25309117)->(3280116041, -32989386)
[ 3.248529] registered taskstats version 1
[ 3.248584] Loading compiled-in X.509 certificates
[ 3.249962] cryptomgr_test (71) used greatest stack depth: 15416 bytes left
[ 3.260651] cryptomgr_test (92) used greatest stack depth: 15192 bytes left
[ 3.263708] PM: Magic number: 10:969:229
[ 3.263947] printk: console [netcon0] enabled
[ 3.263955] netconsole: network logging started
[ 3.264846] Bluetooth: Starting self testing
[ 3.382340] Bluetooth: ECDH test passed in 114733 usecs
[ 3.383368] kworker/u6:2 (96) used greatest stack depth: 14432 bytes left
[ 3.383861] ==================================================================
[ 3.385662] BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
[ 3.387142]
[ 3.387905] race at unknown origin, with read to 0xffff9ec881ad3008 of 1 bytes by task 44 on cpu 0:
[ 3.389778] add_device_randomness+0x20d/0x290
[ 3.389789] release_task+0x231/0xb20
[ 3.389800] wait_consider_task+0x883/0x17d0
[ 3.389809] do_wait+0x2b4/0x4d0
[ 3.389818] kernel_wait+0x71/0xd0
[ 3.389827] call_usermodehelper_exec_work+0xa3/0xb0
[ 3.389838] process_one_work+0x477/0x7d0
[ 3.389845] worker_thread+0x2ec/0x810
[ 3.389851] kthread+0x16d/0x1a0
[ 3.389860] ret_from_fork+0x22/0x30
[ 3.389868]
[ 3.390623] value changed: 0x00 -> 0x43
[ 3.391594]
[ 3.392363] Reported by Kernel Concurrency Sanitizer on:
[ 3.394131] CPU: 0 PID: 44 Comm: kworker/u6:2 Not tainted 5.17.0-rc2-00353-g90c9e950c0de #34
[ 3.394151] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.15.0-1 04/01/2014
[ 3.394190] Workqueue: events_unbound call_usermodehelper_exec_work
[ 3.394217] ==================================================================
[ 3.438291] Bluetooth: SMP test passed in 39410 usecs
[ 3.438364] Bluetooth: Finished self testing
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 16:14 BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290 Paul Menzel
@ 2022-02-07 18:42 ` Jason A. Donenfeld
2022-02-07 21:45 ` Jann Horn
` (2 more replies)
0 siblings, 3 replies; 15+ messages in thread
From: Jason A. Donenfeld @ 2022-02-07 18:42 UTC (permalink / raw)
To: pmenzel; +Cc: Theodore Y. Ts'o, LKML, Dominik Brodowski, Jann Horn
Hi Paul,
Thanks for the report. I assume that this is actually an old bug. Do
you have a vmlinux or a random.o from this kernel you could send me to
double check? Without that, my best guess, which I'd say I have
relatively high confidence about, is that the "1 byte read" is
actually a `movzx eax, cs:lfsr` referring to the `static u8 lfsr`
here, which gets inlined into add_device_randomness:
static int crng_slow_load(const u8 *cp, size_t len)
{
unsigned long flags;
static u8 lfsr = 1;
This was added in 2008 with dc12baacb95f ("random: use a different
mixing algorithm for add_device_randomness()"). My understanding is
that the race here isn't super problematic as we're in kind of a half
assed "low effort" phase anyway. But I'll give it some thought. I'm
CCing Jann as well who reported the original issue that motivated that
change.
Regards,
Jason
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 18:42 ` Jason A. Donenfeld
@ 2022-02-07 21:45 ` Jann Horn
2022-02-07 21:50 ` Jann Horn
2022-02-07 21:49 ` Jann Horn
2022-02-15 9:16 ` Paul Menzel
2 siblings, 1 reply; 15+ messages in thread
From: Jann Horn @ 2022-02-07 21:45 UTC (permalink / raw)
To: Jason A. Donenfeld; +Cc: pmenzel, Theodore Y. Ts'o, LKML, Dominik Brodowski
On Mon, Feb 7, 2022 at 7:42 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> Thanks for the report. I assume that this is actually an old bug. Do
> you have a vmlinux or a random.o from this kernel you could send me to
> double check? Without that, my best guess, which I'd say I have
> relatively high confidence about, is that the "1 byte read" is
> actually a `movzx eax, cs:lfsr` referring to the `static u8 lfsr`
> here, which gets inlined into add_device_randomness:
>
> static int crng_slow_load(const u8 *cp, size_t len)
> {
> unsigned long flags;
> static u8 lfsr = 1;
>
> This was added in 2008 with dc12baacb95f ("random: use a different
> mixing algorithm for add_device_randomness()"). My understanding is
> that the race here isn't super problematic as we're in kind of a half
> assed "low effort" phase anyway. But I'll give it some thought. I'm
> CCing Jann as well who reported the original issue that motivated that
> change.
But the "lfsr" variable is never accessed outside the part of this
method that holds a global spinlock. So that can't really be it,
right?
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 18:42 ` Jason A. Donenfeld
2022-02-07 21:45 ` Jann Horn
@ 2022-02-07 21:49 ` Jann Horn
2022-02-08 0:10 ` Marco Elver
2022-02-15 9:16 ` Paul Menzel
2 siblings, 1 reply; 15+ messages in thread
From: Jann Horn @ 2022-02-07 21:49 UTC (permalink / raw)
To: Jason A. Donenfeld, Marco Elver, Dmitry Vyukov, kasan-dev
Cc: pmenzel, Theodore Y. Ts'o, LKML, Dominik Brodowski
+KCSAN people
On Mon, Feb 7, 2022 at 7:42 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> Thanks for the report. I assume that this is actually an old bug. Do
> you have a vmlinux or a random.o from this kernel you could send me to
> double check? Without that, my best guess, which I'd say I have
> relatively high confidence about,
Maybe KCSAN should go through the same instruction-bytes-dumping thing
as normal BUG() does? That might be helpful for cases like this...
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 21:45 ` Jann Horn
@ 2022-02-07 21:50 ` Jann Horn
2022-02-07 21:53 ` Jann Horn
2022-02-07 21:57 ` Jason A. Donenfeld
0 siblings, 2 replies; 15+ messages in thread
From: Jann Horn @ 2022-02-07 21:50 UTC (permalink / raw)
To: Jason A. Donenfeld; +Cc: pmenzel, Theodore Y. Ts'o, LKML, Dominik Brodowski
On Mon, Feb 7, 2022 at 10:45 PM Jann Horn <jannh@google.com> wrote:
> On Mon, Feb 7, 2022 at 7:42 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> > Thanks for the report. I assume that this is actually an old bug. Do
> > you have a vmlinux or a random.o from this kernel you could send me to
> > double check? Without that, my best guess, which I'd say I have
> > relatively high confidence about, is that the "1 byte read" is
> > actually a `movzx eax, cs:lfsr` referring to the `static u8 lfsr`
> > here, which gets inlined into add_device_randomness:
> >
> > static int crng_slow_load(const u8 *cp, size_t len)
> > {
> > unsigned long flags;
> > static u8 lfsr = 1;
> >
> > This was added in 2008 with dc12baacb95f ("random: use a different
> > mixing algorithm for add_device_randomness()"). My understanding is
> > that the race here isn't super problematic as we're in kind of a half
> > assed "low effort" phase anyway. But I'll give it some thought. I'm
> > CCing Jann as well who reported the original issue that motivated that
> > change.
>
> But the "lfsr" variable is never accessed outside the part of this
> method that holds a global spinlock. So that can't really be it,
> right?
There is a data race in crng_ready(), it just loads from "crng_init"
without READ_ONCE()... maybe that's what KCSAN is noticing?
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 21:50 ` Jann Horn
@ 2022-02-07 21:53 ` Jann Horn
2022-02-07 21:57 ` Jason A. Donenfeld
1 sibling, 0 replies; 15+ messages in thread
From: Jann Horn @ 2022-02-07 21:53 UTC (permalink / raw)
To: Jason A. Donenfeld; +Cc: pmenzel, Theodore Y. Ts'o, LKML, Dominik Brodowski
On Mon, Feb 7, 2022 at 10:50 PM Jann Horn <jannh@google.com> wrote:
>
> On Mon, Feb 7, 2022 at 10:45 PM Jann Horn <jannh@google.com> wrote:
> > On Mon, Feb 7, 2022 at 7:42 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> > > Thanks for the report. I assume that this is actually an old bug. Do
> > > you have a vmlinux or a random.o from this kernel you could send me to
> > > double check? Without that, my best guess, which I'd say I have
> > > relatively high confidence about, is that the "1 byte read" is
> > > actually a `movzx eax, cs:lfsr` referring to the `static u8 lfsr`
> > > here, which gets inlined into add_device_randomness:
> > >
> > > static int crng_slow_load(const u8 *cp, size_t len)
> > > {
> > > unsigned long flags;
> > > static u8 lfsr = 1;
> > >
> > > This was added in 2008 with dc12baacb95f ("random: use a different
> > > mixing algorithm for add_device_randomness()"). My understanding is
> > > that the race here isn't super problematic as we're in kind of a half
> > > assed "low effort" phase anyway. But I'll give it some thought. I'm
> > > CCing Jann as well who reported the original issue that motivated that
> > > change.
> >
> > But the "lfsr" variable is never accessed outside the part of this
> > method that holds a global spinlock. So that can't really be it,
> > right?
>
> There is a data race in crng_ready(), it just loads from "crng_init"
> without READ_ONCE()... maybe that's what KCSAN is noticing?
(Actually, maybe it should technically even be a smp_load_acquire()?
Or do we have anything else that ensures that we can't get ordering
issues here?)
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 21:50 ` Jann Horn
2022-02-07 21:53 ` Jann Horn
@ 2022-02-07 21:57 ` Jason A. Donenfeld
2022-02-07 22:20 ` Jason A. Donenfeld
1 sibling, 1 reply; 15+ messages in thread
From: Jason A. Donenfeld @ 2022-02-07 21:57 UTC (permalink / raw)
To: Jann Horn; +Cc: pmenzel, Theodore Y. Ts'o, LKML, Dominik Brodowski
On Mon, Feb 7, 2022 at 10:50 PM Jann Horn <jannh@google.com> wrote:
> > But the "lfsr" variable is never accessed outside the part of this
> > method that holds a global spinlock. So that can't really be it,
> > right?
Oh, hm, yea. Seems likely.
>
> There is a data race in crng_ready(), it just loads from "crng_init"
> without READ_ONCE()... maybe that's what KCSAN is noticing?
There are lots of data races in crng_ready(), which Dominik has been
fixing up gradually (which is why I CC'd him). However, crng_init is 4
bytes, and that crng_init is read first with a cmpl that will read the
whole thing. Maybe KCSAN's reporting is wrong? But it also says 0x00
-> 0x43, which isn't one of the assigned values of crng_init. Also,
0x20d seems quite far into the body of add_device_randomness, whereas
crng_ready() is checked sort of early on.
Hopefully Paul will send us his vmlinux.
Another possibility is that this is happening on the u8 read of the
buffer *input*, of what release_task->__exit_signal is passing it:
add_device_randomness((const void*) &tsk->se.sum_exec_runtime,
sizeof(unsigned long long));
I haven't yet looked at the locking around tsk->se.sum_exec_runtime.
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 21:57 ` Jason A. Donenfeld
@ 2022-02-07 22:20 ` Jason A. Donenfeld
0 siblings, 0 replies; 15+ messages in thread
From: Jason A. Donenfeld @ 2022-02-07 22:20 UTC (permalink / raw)
To: Jann Horn; +Cc: pmenzel, Theodore Y. Ts'o, LKML, Dominik Brodowski
Narrowing this a bit by looking at the disassembly from as similar as
a config as I could infer, there are three calls to _tsan_read1():
1. ... = lfsr;
2. ... = dest_buf[i % CHACHA_KEY_SIZE];
3. ... ^= src_buf[i % len] ...
1. lfsr, as you mentioned, appears protected by primary_crng.lock.
2. dest_buf is &primary_crng.state, which /should/ be protected by
primary_crng.lock. The only place where it's not is rand_initialize(),
but this is an early boot function that should complete well in
advance of where we are.
3. That would be tsk->se.sum_exec_runtime...
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 21:49 ` Jann Horn
@ 2022-02-08 0:10 ` Marco Elver
2022-02-08 0:12 ` Marco Elver
2022-02-08 0:36 ` Jason A. Donenfeld
0 siblings, 2 replies; 15+ messages in thread
From: Marco Elver @ 2022-02-08 0:10 UTC (permalink / raw)
To: Jann Horn, Jason A. Donenfeld
Cc: Dmitry Vyukov, kasan-dev, pmenzel, Theodore Y. Ts'o, LKML,
Dominik Brodowski
On Mon, 7 Feb 2022 at 22:49, Jann Horn <jannh@google.com> wrote:
> +KCSAN people
>
> On Mon, Feb 7, 2022 at 7:42 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> > Thanks for the report. I assume that this is actually an old bug. Do
> > you have a vmlinux or a random.o from this kernel you could send me to
> > double check? Without that, my best guess, which I'd say I have
> > relatively high confidence about,
>
> Maybe KCSAN should go through the same instruction-bytes-dumping thing
> as normal BUG() does? That might be helpful for cases like this...
A BUG() on x86 actually generates a ud2, and somewhere along the way
it uses pt_regs in show_opcodes(). Generating KCSAN stack traces is
very different, and there's no pt_regs because it's going through
compiler instrumentation.
In general, I wouldn't spend much time on one-sided non-symbolized
KCSAN reports, unless it's obvious what's going on. I've been thinking
of making CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=n the default, because
the one-sided race reports are not very useful. We need to see what
we're racing against. With the normal reports where both threads'
stack traces are shown it's usually much easier to narrow down what's
happening even in the absence of symbolized stack traces.
My suggestion would be to try and get a normal "2-sided" data race report.
I also haven't found something similar in my pile of data race reports
sitting in syzbot moderation.
Jason - if you're interested in KCSAN data race reports in some
subsystems you maintain (I see a few in Wireguard), let me know, and
I'll release them from syzbot's moderation queue. The way we're trying
to do it with KCSAN is that we pre-moderate and ask maintainers if
they're happy to be forwarded all reports that syzbot finds (currently
some Networking and RCU, though the latter finds almost all data races
via KCSAN-enabled rcutorture).
Thanks,
-- Marco
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-08 0:10 ` Marco Elver
@ 2022-02-08 0:12 ` Marco Elver
2022-02-08 0:36 ` Jason A. Donenfeld
1 sibling, 0 replies; 15+ messages in thread
From: Marco Elver @ 2022-02-08 0:12 UTC (permalink / raw)
To: Jann Horn, Jason A. Donenfeld
Cc: Dmitry Vyukov, kasan-dev, pmenzel, Theodore Y. Ts'o, LKML,
Dominik Brodowski
On Tue, 8 Feb 2022 at 01:10, Marco Elver <elver@google.com> wrote:
>
> On Mon, 7 Feb 2022 at 22:49, Jann Horn <jannh@google.com> wrote:
> > +KCSAN people
> >
> > On Mon, Feb 7, 2022 at 7:42 PM Jason A. Donenfeld <Jason@zx2c4.com> wrote:
> > > Thanks for the report. I assume that this is actually an old bug. Do
> > > you have a vmlinux or a random.o from this kernel you could send me to
> > > double check? Without that, my best guess, which I'd say I have
> > > relatively high confidence about,
> >
> > Maybe KCSAN should go through the same instruction-bytes-dumping thing
> > as normal BUG() does? That might be helpful for cases like this...
>
> A BUG() on x86 actually generates a ud2, and somewhere along the way
> it uses pt_regs in show_opcodes(). Generating KCSAN stack traces is
> very different, and there's no pt_regs because it's going through
> compiler instrumentation.
>
> In general, I wouldn't spend much time on one-sided non-symbolized
> KCSAN reports, unless it's obvious what's going on. I've been thinking
> of making CONFIG_KCSAN_REPORT_VALUE_CHANGE_ONLY=n the default, because
(That should have been KCSAN_REPORT_RACE_UNKNOWN_ORIGIN=n ... copy-paste error.)
> the one-sided race reports are not very useful. We need to see what
> we're racing against. With the normal reports where both threads'
> stack traces are shown it's usually much easier to narrow down what's
> happening even in the absence of symbolized stack traces.
>
> My suggestion would be to try and get a normal "2-sided" data race report.
>
> I also haven't found something similar in my pile of data race reports
> sitting in syzbot moderation.
>
> Jason - if you're interested in KCSAN data race reports in some
> subsystems you maintain (I see a few in Wireguard), let me know, and
> I'll release them from syzbot's moderation queue. The way we're trying
> to do it with KCSAN is that we pre-moderate and ask maintainers if
> they're happy to be forwarded all reports that syzbot finds (currently
> some Networking and RCU, though the latter finds almost all data races
> via KCSAN-enabled rcutorture).
>
> Thanks,
> -- Marco
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-08 0:10 ` Marco Elver
2022-02-08 0:12 ` Marco Elver
@ 2022-02-08 0:36 ` Jason A. Donenfeld
2022-02-08 9:23 ` Marco Elver
1 sibling, 1 reply; 15+ messages in thread
From: Jason A. Donenfeld @ 2022-02-08 0:36 UTC (permalink / raw)
To: Marco Elver
Cc: Jann Horn, Dmitry Vyukov, kasan-dev, pmenzel,
Theodore Y. Ts'o, LKML, Dominik Brodowski
Hi Marco,
On 2/8/22, Marco Elver <elver@google.com> wrote:
> Jason - if you're interested in KCSAN data race reports in some
> subsystems you maintain (I see a few in Wireguard), let me know, and
> I'll release them from syzbot's moderation queue. The way we're trying
> to do it with KCSAN is that we pre-moderate and ask maintainers if
> they're happy to be forwarded all reports that syzbot finds (currently
> some Networking and RCU, though the latter finds almost all data races
> via KCSAN-enabled rcutorture).
Oh that'd be great. Please feel free to forward whatever for WireGuard
or random.c to jason@zx2c4.com and I'll gladly try to fix what needs
fixing.
Jason
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-08 0:36 ` Jason A. Donenfeld
@ 2022-02-08 9:23 ` Marco Elver
0 siblings, 0 replies; 15+ messages in thread
From: Marco Elver @ 2022-02-08 9:23 UTC (permalink / raw)
To: Jason A. Donenfeld
Cc: Jann Horn, Dmitry Vyukov, kasan-dev, pmenzel,
Theodore Y. Ts'o, LKML, Dominik Brodowski
On Tue, 8 Feb 2022 at 01:36, Jason A. Donenfeld <Jason@zx2c4.com> wrote:
>
> Hi Marco,
>
> On 2/8/22, Marco Elver <elver@google.com> wrote:
> > Jason - if you're interested in KCSAN data race reports in some
> > subsystems you maintain (I see a few in Wireguard), let me know, and
> > I'll release them from syzbot's moderation queue. The way we're trying
> > to do it with KCSAN is that we pre-moderate and ask maintainers if
> > they're happy to be forwarded all reports that syzbot finds (currently
> > some Networking and RCU, though the latter finds almost all data races
> > via KCSAN-enabled rcutorture).
>
> Oh that'd be great. Please feel free to forward whatever for WireGuard
> or random.c to jason@zx2c4.com and I'll gladly try to fix what needs
> fixing.
Great! I've released everything I could see right now.
Thanks,
-- Marco
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-07 18:42 ` Jason A. Donenfeld
2022-02-07 21:45 ` Jann Horn
2022-02-07 21:49 ` Jann Horn
@ 2022-02-15 9:16 ` Paul Menzel
2022-02-15 11:44 ` Jason A. Donenfeld
2 siblings, 1 reply; 15+ messages in thread
From: Paul Menzel @ 2022-02-15 9:16 UTC (permalink / raw)
To: Jason A. Donenfeld
Cc: Theodore Y. Ts'o, LKML, Dominik Brodowski, Jann Horn
Dear Jason,
Thank you for your quick response, and sorry for the late reply.
Am 07.02.22 um 19:42 schrieb Jason A. Donenfeld:
> Thanks for the report. I assume that this is actually an old bug. Do
> you have a vmlinux or a random.o from this kernel you could send me to
> double check?
I had unfortunately already overwritten these files. I was unable to
fully reproduce the same trace with a build from the same commit, and
only got:
```
[…]
[ 12.819273] BUG: KCSAN: data-race in _mix_pool_bytes+0x5d/0x1c0
[ 12.822917] race at unknown origin, with read to 0xffffa21c07003009
of 1 bytes by task 1035 on cpu 0:
[ 12.823580] _mix_pool_bytes+0x5d/0x1c0
[ 12.823678] add_device_randomness+0x97/0x290
[ 12.823691] release_task+0x231/0xb20
[ 12.823735] wait_consider_task+0x883/0x17d0
[ 12.823755] do_wait+0x35f/0x4d0
[ 12.823768] kernel_wait4+0xdb/0x180
[ 12.823778] __do_sys_wait4+0x85/0x90
[ 12.823787] __x64_sys_wait4+0x49/0x50
[ 12.823797] do_syscall_64+0x39/0x80
[ 12.823819] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 12.824028] value changed: 0x56 -> 0xc1
[ 12.824415] Reported by Kernel Concurrency Sanitizer on:
[ 12.824688] CPU: 0 PID: 1035 Comm: postfix-script Not tainted
5.17.0-rc2-00352-g90c9e950c0de #40
[ 12.824705] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.15.0-1 04/01/2014
[…]
```
So instead of the former (used as subject line)
add_device_randomness+0x20d/0x290
there is
add_device_randomness+0x97/0x290
I uploaded `random.o` [1].
Kind regards,
Paul
[1]: https://owww.molgen.mpg.de/~pmenzel/random.o
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-15 9:16 ` Paul Menzel
@ 2022-02-15 11:44 ` Jason A. Donenfeld
2022-02-15 12:12 ` Oleg Nesterov
0 siblings, 1 reply; 15+ messages in thread
From: Jason A. Donenfeld @ 2022-02-15 11:44 UTC (permalink / raw)
To: Paul Menzel
Cc: Theodore Y. Ts'o, LKML, Dominik Brodowski, Jann Horn,
Dmitry Vyukov, Marco Elver, Nicolas Pitre, Rik van Riel,
Oleg Nesterov
Hi Paul,
Thanks for the new report. This looks like likely the same sort of
issue as before -- it's on a 1 byte read of the data that's being
passed to add_device_randomness by release_task(). It looks like there
might be a race in release_task():
void release_task(struct task_struct *p)
{
[...]
cgroup_release(p);
write_lock_irq(&tasklist_lock);
ptrace_release_task(p);
thread_pid = get_pid(p->thread_pid);
__exit_signal(p);
[...]
}
static void __exit_signal(struct task_struct *tsk)
{
[...]
add_device_randomness((const void*) &tsk->se.sum_exec_runtime,
sizeof(unsigned long long));
[...]
}
Apparently the data that is being read by add_device_randomness() is
being modified while it's being read. This would be whatever is in
`tsk->se.sum_exec_runtime`.
I'm not sure what's happening there, if this is "normal" and the task
can be scheduled out while exiting, causing the schedule to add to
sum_exec_runtime, or what. CCing some people who seem to have touched
this code, and maybe that'll help illuminate things.
Thanks,
Jason
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290
2022-02-15 11:44 ` Jason A. Donenfeld
@ 2022-02-15 12:12 ` Oleg Nesterov
0 siblings, 0 replies; 15+ messages in thread
From: Oleg Nesterov @ 2022-02-15 12:12 UTC (permalink / raw)
To: Jason A. Donenfeld
Cc: Paul Menzel, Theodore Y. Ts'o, LKML, Dominik Brodowski,
Jann Horn, Dmitry Vyukov, Marco Elver, Nicolas Pitre,
Rik van Riel
On 02/15, Jason A. Donenfeld wrote:
>
> void release_task(struct task_struct *p)
> {
> [...]
> cgroup_release(p);
>
> write_lock_irq(&tasklist_lock);
> ptrace_release_task(p);
> thread_pid = get_pid(p->thread_pid);
> __exit_signal(p);
> [...]
> }
> static void __exit_signal(struct task_struct *tsk)
> {
> [...]
> add_device_randomness((const void*) &tsk->se.sum_exec_runtime,
> sizeof(unsigned long long));
> [...]
> }
>
> Apparently the data that is being read by add_device_randomness() is
> being modified while it's being read. This would be whatever is in
> `tsk->se.sum_exec_runtime`.
>
> I'm not sure what's happening there, if this is "normal" and the task
> can be scheduled out while exiting, causing the schedule to add to
> sum_exec_runtime, or what.
Yes, this is normal.
The parent can call release_task(child) right after the child has passed
exit_notify(), the exiting child still runs and can be scheduled out until
it does the last schedule from do_task_dead().
Oleg.
^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2022-02-15 12:13 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-02-07 16:14 BUG: KCSAN: data-race in add_device_randomness+0x20d/0x290 Paul Menzel
2022-02-07 18:42 ` Jason A. Donenfeld
2022-02-07 21:45 ` Jann Horn
2022-02-07 21:50 ` Jann Horn
2022-02-07 21:53 ` Jann Horn
2022-02-07 21:57 ` Jason A. Donenfeld
2022-02-07 22:20 ` Jason A. Donenfeld
2022-02-07 21:49 ` Jann Horn
2022-02-08 0:10 ` Marco Elver
2022-02-08 0:12 ` Marco Elver
2022-02-08 0:36 ` Jason A. Donenfeld
2022-02-08 9:23 ` Marco Elver
2022-02-15 9:16 ` Paul Menzel
2022-02-15 11:44 ` Jason A. Donenfeld
2022-02-15 12:12 ` Oleg Nesterov
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.