Re: [x86, kaslr] INFO: possible circular locking dependency detected

From: Kees Cook
Date: Mon Mar 24 2014 - 00:07:37 EST

Next message: Zhang Rui: "Re: [PATCH V4 07/11] ACPI: use platform bus as the default bus for _HID enumeration"
Previous message: Zhang Rui: "[PATCH] ACPI: introduce .handle_children flag for acpi scan handler"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Sun, Mar 23, 2014 at 8:07 PM, Fengguang Wu <fengguang.wu@xxxxxxxxx> wrote:
> Hi Kees,
>
> FYI, the problem is still in linux-next, first bad commit is
>
> git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git x86/kaslr
> commit e2b32e6785138d92d2a40e0d0473575c8c7310a2
> Author: Kees Cook <keescook@xxxxxxxxxxxx>
> AuthorDate: Tue Feb 25 16:59:17 2014 -0800
> Commit: H. Peter Anvin <hpa@xxxxxxxxxxxxxxx>
> CommitDate: Tue Feb 25 17:07:26 2014 -0800
>
> x86, kaslr: randomize module base load address

Peter, can you take the patch that was sent to fix this?

https://lkml.org/lkml/2014/3/10/531

-Kees

>
>
> +----------------------------------------------------------+-----------+------------+---------------+
> | | v3.14-rc4 | e2b32e6785 | next-20140321 |
> +----------------------------------------------------------+-----------+------------+---------------+
> | boot_successes | 589 | 53 | 5 |
> | boot_failures | 11 | 147 | 14 |
> | BUG:unable_to_handle_kernel_paging_request | 8 | 3 | |
> | BUG:kernel_boot_crashed | 1 | | |
> | BUG:kernel_boot_hang | 2 | 4 | |
> | WARNING:CPU:PID:at_mm/page_alloc.c:free_area_init_node() | 3 | | |
> | Oops:SMP_DEBUG_PAGEALLOC | 3 | 1 | |
> | EIP_is_at_strnlen | 3 | | |
> | Kernel_panic-not_syncing:Fatal_exception | 3 | 1 | |
> | backtrace:free_area_init_node | 3 | | |
> | backtrace:warn_slowpath_null | 3 | | |
> | backtrace:free_area_init_nodes | 3 | | |
> | backtrace:zone_sizes_init | 3 | | |
> | backtrace:paging_init | 3 | | |
> | backtrace:native_pagetable_init | 3 | | |
> | backtrace:printk | 3 | | |
> | INFO:possible_circular_locking_dependency_detected | 0 | 139 | 11 |
> | backtrace:register_kprobe | 0 | 139 | 11 |
> | backtrace:init_test_probes | 0 | 139 | 11 |
> | backtrace:init_kprobes | 0 | 139 | 11 |
> | backtrace:kernel_init_freeable | 0 | 140 | 11 |
> | backtrace:kprobe_optimizer | 0 | 139 | 11 |
> | BUG:soft_lockup-CPU_stuck_for_s | 0 | 1 | |
> | EIP_is_at_raw_write_unlock_irq | 0 | 1 | |
> | Kernel_panic-not_syncing:softlockup:hung_tasks | 0 | 1 | |
> | backtrace:cryptomgr_test | 0 | 1 | |
> | EIP_is_at__change_page_attr_set_clr | 0 | 1 | |
> | backtrace:set_memory_np | 0 | 1 | |
> | backtrace:free_init_pages | 0 | 1 | |
> | backtrace:populate_rootfs | 0 | 1 | |
> | BUG:Int_CR2(null) | 0 | 1 | |
> | backtrace:kvm_get_tsc_khz | 0 | 1 | |
> | backtrace:kvmclock_init | 0 | 1 | |
> | INFO:suspicious_RCU_usage | 0 | 0 | 3 |
> | INFO:rcu_sched_detected_stalls_on_CPUs/tasks | 0 | 0 | 10 |
> | INFO:task_blocked_for_more_than_seconds | 0 | 0 | 14 |
> | INFO:lockdep_is_turned_off | 0 | 0 | 14 |
> | EIP_is_at_native_safe_halt | 0 | 0 | 14 |
> | EIP_is_at_default_send_IPI_mask_logical | 0 | 0 | 14 |
> | Kernel_panic-not_syncing:hung_task:blocked_tasks | 0 | 0 | 14 |
> | backtrace:do_fork | 0 | 0 | 3 |
> | backtrace:SyS_clone | 0 | 0 | 3 |
> | backtrace:vfs_read | 0 | 0 | 2 |
> | backtrace:SyS_read | 0 | 0 | 2 |
> | backtrace:cpu_startup_entry | 0 | 0 | 14 |
> | backtrace:watchdog | 0 | 0 | 14 |
> | backtrace:register_kretprobes | 0 | 0 | 11 |
> | backtrace:vfs_write | 0 | 0 | 1 |
> | backtrace:SyS_write | 0 | 0 | 1 |
> +----------------------------------------------------------+-----------+------------+---------------+
>
> [ 5.027064] Kprobe smoke test started
> [ 5.123444]
> [ 5.124372] ======================================================
> [ 5.125977] [ INFO: possible circular locking dependency detected ]
> [ 5.126685] 3.14.0-rc7-next-20140321 #16 Not tainted
> [ 5.126685] -------------------------------------------------------
> [ 5.126685] kworker/1:1/26 is trying to acquire lock:
> [ 5.126685] (text_mutex){+.+.+.}, at: [<d197e40d>] kprobe_optimizer+0x270/0x448
> [ 5.126685]
> [ 5.126685] but task is already holding lock:
> [ 5.126685] (module_mutex){+.+...}, at: [<d197e1d7>] kprobe_optimizer+0x3a/0x448
> [ 5.126685]
> [ 5.126685] which lock already depends on the new lock.
> [ 5.126685]
> [ 5.126685]
> [ 5.126685] the existing dependency chain (in reverse order) is:
> [ 5.126685]
> -> #2 (module_mutex){+.+...}:
> [ 5.126685] [<d1103e6b>] __lock_acquire+0x226c/0x29cc
> [ 5.126685] [<d11046b3>] lock_acquire+0xe8/0x149
> [ 5.126685] [<d19701ca>] mutex_lock_nested+0x8d/0xa9e
> [ 5.126685] [<d105f26b>] module_alloc+0xa0/0x153
> [ 5.126685] [<d1167e7f>] alloc_insn_page+0x1b/0x2b
> [ 5.126685] [<d197fd32>] __get_insn_slot+0x1ff/0x2a8
> [ 5.126685] [<d197a3f7>] arch_prepare_kprobe+0x7b/0x1b4
> [ 5.126685] [<d1981d33>] register_kprobe+0x89b/0xb1f
> [ 5.126685] [<d116520f>] init_test_probes+0x8c/0x8ed
> [ 5.126685] [<d1f3ceaa>] init_kprobes+0x260/0x288
> [ 5.126685] [<d10021e2>] do_one_initcall+0x133/0x2b2
> [ 5.126685] [<d1f09aee>] kernel_init_freeable+0x483/0x5ff
> [ 5.126685] [<d1955732>] kernel_init+0x16/0x1fa
> [ 5.126685] [<d1982d61>] ret_from_kernel_thread+0x21/0x30
> [ 5.126685]
> -> #1 (kprobe_insn_slots.mutex){+.+.+.}:
> [ 5.126685] [<d1103e6b>] __lock_acquire+0x226c/0x29cc
> [ 5.126685] [<d11046b3>] lock_acquire+0xe8/0x149
> [ 5.126685] [<d19701ca>] mutex_lock_nested+0x8d/0xa9e
> [ 5.126685] [<d197fb56>] __get_insn_slot+0x23/0x2a8
> [ 5.126685] [<d197a3f7>] arch_prepare_kprobe+0x7b/0x1b4
> [ 5.126685] [<d1981d33>] register_kprobe+0x89b/0xb1f
> [ 5.126685] [<d116520f>] init_test_probes+0x8c/0x8ed
> [ 5.126685] [<d1f3ceaa>] init_kprobes+0x260/0x288
> [ 5.126685] [<d10021e2>] do_one_initcall+0x133/0x2b2
> [ 5.126685] [<d1f09aee>] kernel_init_freeable+0x483/0x5ff
> [ 5.126685] [<d1955732>] kernel_init+0x16/0x1fa
> [ 5.126685] [<d1982d61>] ret_from_kernel_thread+0x21/0x30
> [ 5.126685]
> -> #0 (text_mutex){+.+.+.}:
> [ 5.126685] [<d11003c1>] check_prev_add+0x1ac/0xb33
> [ 5.126685] [<d1103e6b>] __lock_acquire+0x226c/0x29cc
> [ 5.126685] [<d11046b3>] lock_acquire+0xe8/0x149
> [ 5.126685] [<d19701ca>] mutex_lock_nested+0x8d/0xa9e
> [ 5.126685] [<d197e40d>] kprobe_optimizer+0x270/0x448
> [ 5.126685] [<d10ad1ae>] process_one_work+0x3a4/0x6a8
> [ 5.126685] [<d10af44e>] worker_thread+0x349/0x5dd
> [ 5.126685] [<d10bab6e>] kthread+0x13f/0x152
> [ 5.126685] [<d1982d61>] ret_from_kernel_thread+0x21/0x30
> [ 5.126685]
> [ 5.126685] other info that might help us debug this:
> [ 5.126685]
> [ 5.126685] Chain exists of:
> text_mutex --> kprobe_insn_slots.mutex --> module_mutex
>
> [ 5.126685] Possible unsafe locking scenario:
> [ 5.126685]
> [ 5.126685] CPU0 CPU1
> [ 5.126685] ---- ----
> [ 5.126685] lock(module_mutex);
> [ 5.126685] lock(kprobe_insn_slots.mutex);
> [ 5.126685] lock(module_mutex);
> [ 5.126685] lock(text_mutex);
> [ 5.126685]
> [ 5.126685] *** DEADLOCK ***
> [ 5.126685]
> [ 5.126685] 5 locks held by kworker/1:1/26:
> [ 5.126685] #0: ("events"){.+.+..}, at: [<d10ad11d>] process_one_work+0x313/0x6a8
> [ 5.126685] #1: ((optimizing_work).work){+.+...}, at: [<d10ad11d>] process_one_work+0x313/0x6a8
> [ 5.126685] #2: (kprobe_mutex){+.+.+.}, at: [<d197e1bd>] kprobe_optimizer+0x20/0x448
> [ 5.126685] #3: (module_mutex){+.+...}, at: [<d197e1d7>] kprobe_optimizer+0x3a/0x448
> [ 5.126685] #4: (cpu_hotplug.lock){++++++}, at: [<d1080552>] get_online_cpus+0x51/0xc3
> [ 5.126685]
> [ 5.126685] stack backtrace:
> [ 5.126685] CPU: 1 PID: 26 Comm: kworker/1:1 Not tainted 3.14.0-rc7-next-20140321 #16
> [ 5.126685] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> [ 5.126685] Workqueue: events kprobe_optimizer
> [ 5.126685] d35a15c0 d2c5dd74 d1966a95 d229b38c d2c5dda4 d195f07e d1c9d76f d1c9d521
> [ 5.126685] d1c9d4e9 d1c9d50a d1c9d4e9 d35a15c0 d2c5ddb8 d35a1a64 d35a1a94 d35a15c0
> [ 5.126685] d2c5dde8 d11003c1 d35a1a64 d35a1a7c d2492de4 d11001e5 00000009 d229b27c
> [ 5.126685] Call Trace:
> [ 5.126685] [<d1966a95>] dump_stack+0xb8/0x108
> [ 5.126685] [<d195f07e>] print_circular_bug+0x5ec/0x638
> [ 5.126685] [<d11003c1>] check_prev_add+0x1ac/0xb33
> [ 5.126685] [<d11001e5>] ? check_irq_usage+0xf0/0x120
> [ 5.126685] [<d1103e6b>] ? __lock_acquire+0x226c/0x29cc
> [ 5.126685] [<d1103e6b>] __lock_acquire+0x226c/0x29cc
> [ 5.126685] [<d11046b3>] lock_acquire+0xe8/0x149
> [ 5.126685] [<d197e40d>] ? kprobe_optimizer+0x270/0x448
> [ 5.126685] [<d19701ca>] mutex_lock_nested+0x8d/0xa9e
> [ 5.126685] [<d197e40d>] ? kprobe_optimizer+0x270/0x448
> [ 5.126685] [<d197363d>] ? mutex_unlock+0x16/0x26
> [ 5.126685] [<d10805b1>] ? get_online_cpus+0xb0/0xc3
> [ 5.126685] [<d197e40d>] kprobe_optimizer+0x270/0x448
> [ 5.126685] [<d10ad1ae>] process_one_work+0x3a4/0x6a8
> [ 5.126685] [<d10ad11d>] ? process_one_work+0x313/0x6a8
> [ 5.126685] [<d10af44e>] worker_thread+0x349/0x5dd
> [ 5.126685] [<d10af105>] ? manage_workers.isra.20+0x3fc/0x3fc
> [ 5.126685] [<d10bab6e>] kthread+0x13f/0x152
> [ 5.126685] [<d10c0000>] ? __hrtimer_start_range_ns+0x413/0x635
> [ 5.126685] [<d1982d61>] ret_from_kernel_thread+0x21/0x30
> [ 5.126685] [<d10baa2f>] ? kthread_stop+0x103/0x103
>
> git bisect start 3b55c3c0ec2eb3f163f15559f3962df717f53ccb v3.13 --
> git bisect good 3962dfbe22a8d65e4162354cc859440293d85524 # 16:55 27+ 2 Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs
> git bisect good dcb99fd9b08cfe1afe426af4d8d3cbc429190f15 # 17:15 27+ 0 Linux 3.14-rc7
> git bisect good 5a02b8848ab78148f442126c6c7e32553326c00d # 17:38 27+ 0 Merge remote-tracking branch 'thermal/next'
> git bisect good 1b89b74cc212e138793d688321f8424a96a1c534 # 18:04 27+ 1 Merge remote-tracking branch 'dt-rh/for-next'
> git bisect bad 6ecd774cc7ff8b15a950c827630b852c0dc48ab2 # 18:43 10- 1 Merge remote-tracking branch 'char-misc/char-misc-next'
> git bisect bad d8be03aa8bf754fa0ec3a20885a2387e43a418fe # 19:07 16- 7 Merge remote-tracking branch 'percpu/for-next'
> git bisect bad 0e56c90c132b64427c8c55fd85003ec1f17dba6d # 19:45 36- 4 Merge remote-tracking branch 'edac-amd/for-next'
> git bisect bad 67ae3b36794de69d58e66fb50be0fa0d68574c17 # 20:12 29- 8 Merge remote-tracking branch 'tip/auto-latest'
> git bisect good e224ef010790d873c4672a408f442c08b901567f # 20:50 200+ 1 Merge remote-tracking branch 'spi/for-next'
> git bisect good a49712343611eb2aca50b2034910e8873b453118 # 21:15 200+ 5 Merge branch 'perf/core'
> git bisect good 626bfe396b8bfe0c2c94fe44bc985103abfe4b6f # 21:46 200+ 2 Merge branch 'x86/apic'
> git bisect good 72a500453a77e0980c0c2b4ed9fe8b521e7ac523 # 22:25 200+ 5 Merge branch 'x86/debug'
> git bisect bad c519db7a10228d5f0d6baf3deaa2c869f8b57bb9 # 22:55 65- 7 Merge branch 'x86/kaslr'
> git bisect good 3db4cafdfd05717dc939780134e53023a3c1f15f # 23:42 200+ 9 x86/boot: Fix non-EFI build
> git bisect good 4fd69331ad227a4d8de26592d017b73e00caca9f # 00:28 200+ 4 Merge remote-tracking branch 'tip/x86/urgent' into efi-for-mingo
> git bisect good 4f72c11ae1f01bfc65faf7687b7fdab5ab5ed04a # 01:04 200+ 6 Merge branch 'x86/efi'
> git bisect good 9d90b2ca54ad8b0b9f3ff20e9a93fb07450b0fb1 # 01:54 200+ 5 Merge branch 'x86/hash'
> git bisect good 564ce606924e378825118a95937d9b03a6f1d1bf # 02:16 200+ 4 Merge branch 'x86/iommu'
> git bisect bad e2b32e6785138d92d2a40e0d0473575c8c7310a2 # 02:38 8- 13 x86, kaslr: randomize module base load address
> # first bad commit: [e2b32e6785138d92d2a40e0d0473575c8c7310a2] x86, kaslr: randomize module base load address
> git bisect good cfbf8d4857c26a8a307fb7cd258074c9dcd8c691 # 03:36 600+ 11 Linux 3.14-rc4
> git bisect bad 06ed26d1de59ce7cbbe68378b7e470be169750e5 # 03:36 0- 14 Add linux-next specific files for 20140321
> git bisect good 774868c7094d35b4518be3d0e654de000a5d11fc # 04:29 600+ 15 Merge branch 'perf-urgent-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
> git bisect bad 06ed26d1de59ce7cbbe68378b7e470be169750e5 # 04:29 0- 14 Add linux-next specific files for 20140321
>
>
> It's very reproducible with this script:
>
> #!/bin/bash
>
> kernel=$1
> initrd=yocto-minimal-i386.cgz
>
> wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/blob/master/initrd/yocto-minimal-i386.cgz
>
> kvm=(
> qemu-system-x86_64 -cpu kvm64 -enable-kvm
> -kernel $kernel
> -initrd $initrd
> -smp 2
> -m 256M
> -net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio
> -net user,vlan=0
> -net nic,vlan=1,model=e1000
> -net user,vlan=1
> -boot order=nc
> -no-reboot
> -watchdog i6300esb
> -serial stdio
> -display none
> -monitor null
> )
>
> append=(
> debug
> sched_debug
> apic=debug
> ignore_loglevel
> sysrq_always_enabled
> panic=10
> prompt_ramdisk=0
> earlyprintk=ttyS0,115200
> console=ttyS0,115200
> console=tty0
> vga=normal
> root=/dev/ram0
> rw
> )
>
> "${kvm[@]}" --append "${append[*]}"
>
> Thanks,
> Fengguang

--
Kees Cook
Chrome OS Security
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Zhang Rui: "Re: [PATCH V4 07/11] ACPI: use platform bus as the default bus for _HID enumeration"
Previous message: Zhang Rui: "[PATCH] ACPI: introduce .handle_children flag for acpi scan handler"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]