From mboxrd@z Thu Jan 1 00:00:00 1970 From: Lingzhu Xiang Subject: EFI pstore: BUG: scheduling while atomic, and possible circular locking dependency Date: Thu, 22 Nov 2012 10:57:40 +0800 Message-ID: <50AD94A4.4030100@redhat.com> Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Return-path: Sender: linux-efi-owner-u79uwXL29TY76Z2rM5mHXA@public.gmane.org To: linux-efi-u79uwXL29TY76Z2rM5mHXA@public.gmane.org, Matthew Garrett Cc: Tony Luck , Kees Cook , Anton Vorontsov , Matt Fleming List-Id: linux-efi@vger.kernel.org Debug kernels generate such messages when doing EFI pstore read and write. Kernel version ranges from 3.2 to 3.7-rc. Always reproducible on QEMU/OVMF instances and a Thinkpad T520 laptop. I hope this report helps. mount pstore and crash ====================== [ 83.504275] SysRq : Trigger a crash [ 83.505022] BUG: unable to handle kernel NULL pointer dereference at (null) [ 83.505022] IP: [] sysrq_handle_crash+0x16/0x20 [ 83.505022] PGD 9ea4067 PUD 9e1a067 PMD 0 [ 83.505022] Oops: 0002 [#1] SMP [ 83.505022] Modules linked in: ipt_MASQUERADE nf_conntrack_netbios_ns nf_conntrack_broadcast ip6table_mangle ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables iptable_nat nf_nat_ipv4 nf_nat iptable_mangle nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack vfat fat microcode virtio_net i2c_piix4 i2c_core [ 83.505022] CPU 2 [ 83.505022] Pid: 797, comm: bash Tainted: G W 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 [ 83.505022] RIP: 0010:[] [] sysrq_handle_crash+0x16/0x20 [ 83.505022] RSP: 0018:ffff88001a7abe28 EFLAGS: 00010096 [ 83.505022] RAX: 000000000000000f RBX: ffffffff81cc28a0 RCX: 0000000000000000 [ 83.505022] RDX: ffff880005182690 RSI: 0000000000000000 RDI: 0000000000000063 [ 83.505022] RBP: ffff88001a7abe28 R08: 0000000000000001 R09: 0000000000000001 [ 83.505022] R10: 0000000000000002 R11: 000000000000029c R12: 0000000000000063 [ 83.505022] R13: 0000000000000282 R14: 0000000000000000 R15: 000000000000000a [ 83.505022] FS: 00007fa8d353a740(0000) GS:ffff88001b000000(0000) knlGS:0000000000000000 [ 83.505022] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 83.505022] CR2: 0000000000000000 CR3: 0000000007fd3000 CR4: 00000000000406e0 [ 83.505022] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 83.505022] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 83.505022] Process bash (pid: 797, threadinfo ffff88001a7aa000, task ffff880005182690) [ 83.505022] Stack: [ 83.505022] ffff88001a7abe68 ffffffff81416547 ffff88001a7abe68 0000000000000002 [ 83.505022] ffff8800188aa940 ffffffff814165b0 ffff880016cde2b8 ffff88001a7abf50 [ 83.505022] ffff88001a7abe98 ffffffff814165fa ffff88001a7abe98 00007fa8d3541000 [ 83.505022] Call Trace: [ 83.505022] [] __handle_sysrq+0x127/0x190 [ 83.505022] [] ? __handle_sysrq+0x190/0x190 [ 83.505022] [] write_sysrq_trigger+0x4a/0x50 [ 83.505022] [] proc_reg_write+0x80/0xc0 [ 83.505022] [] vfs_write+0xaf/0x190 [ 83.505022] [] sys_write+0x55/0xa0 [ 83.505022] [] system_call_fastpath+0x16/0x1b [ 83.505022] Code: c1 f7 ff ff eb d8 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 66 66 66 66 90 55 c7 05 cc f4 cb 00 01 00 00 00 48 89 e5 0f ae f8 04 25 00 00 00 00 01 5d c3 66 66 66 66 90 55 31 c0 48 89 e5 [ 83.505022] RIP [] sysrq_handle_crash+0x16/0x20 [ 83.505022] RSP [ 83.505022] CR2: 0000000000000000 [ 83.505022] ---[ end trace b0c0c16a378b5fe5 ]--- [ 83.505022] BUG: sleeping function called from invalid context at mm/slub.c:928 [ 83.505022] in_atomic(): 1, irqs_disabled(): 1, pid: 797, name: bash [ 83.505022] INFO: lockdep is turned off. [ 83.505022] irq event stamp: 54760 [ 83.505022] hardirqs last enabled at (54759): [] retint_swapgs+0x13/0x1b [ 83.505022] hardirqs last disabled at (54760): [] _raw_spin_lock_irqsave+0x32/0xb0 [ 83.505022] softirqs last enabled at (54672): [] __do_softirq+0x167/0x3d0 [ 83.505022] softirqs last disabled at (54655): [] call_softirq+0x1c/0x30 [ 83.505022] Pid: 797, comm: bash Tainted: G D W 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 [ 83.505022] Call Trace: [ 83.505022] [] ? print_irqtrace_events+0xd0/0xe0 [ 83.505022] [] __might_sleep+0x18d/0x250 [ 83.505022] [] __kmalloc+0x67/0x2d0 [ 83.505022] [] ? efivar_create_sysfs_entry+0x3b/0x1b0 [ 83.505022] [] efivar_create_sysfs_entry+0x3b/0x1b0 [ 83.505022] [] efi_pstore_write+0x333/0x3a0 [ 83.505022] [] ? kmsg_dump_get_buffer+0x24e/0x2b0 [ 83.505022] [] ? pstore_dump+0x195/0x210 [ 83.505022] [] pstore_dump+0x12f/0x210 [ 83.505022] [] kmsg_dump+0xf9/0x240 [ 83.505022] [] ? kmsg_dump+0x25/0x240 [ 83.505022] [] oops_exit+0x29/0x30 [ 83.505022] [] oops_end+0x73/0xe0 [ 83.505022] [] no_context+0x258/0x283 [ 83.505022] [] __bad_area_nosemaphore+0x1ca/0x1e9 [ 83.505022] [] bad_area_nosemaphore+0x13/0x15 [ 83.505022] [] __do_page_fault+0x2ae/0x580 [ 83.505022] [] ? trace_hardirqs_off+0xd/0x10 [ 83.505022] [] ? _raw_spin_unlock_irqrestore+0x77/0x80 [ 83.505022] [] ? console_unlock+0x1ed/0x4a0 [ 83.505022] [] do_page_fault+0xe/0x10 [ 83.505022] [] do_async_page_fault+0x35/0xa0 [ 83.505022] [] async_page_fault+0x28/0x30 [ 83.505022] [] ? sysrq_handle_crash+0x16/0x20 [ 83.505022] [] __handle_sysrq+0x127/0x190 [ 83.505022] [] ? __handle_sysrq+0x190/0x190 [ 83.505022] [] write_sysrq_trigger+0x4a/0x50 [ 83.505022] [] proc_reg_write+0x80/0xc0 [ 83.505022] [] vfs_write+0xaf/0x190 [ 83.505022] [] sys_write+0x55/0xa0 [ 83.505022] [] system_call_fastpath+0x16/0x1b [ 83.596022] BUG: scheduling while atomic: bash/797/0x10000004 [ 83.596744] INFO: lockdep is turned off. [ 83.603006] Modules linked in: ipt_MASQUERADE nf_conntrack_netbios_ns nf_conntrack_broadcast ip6table_mangle ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables iptable_nat nf_nat_ipv4 nf_nat iptable_mangle nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack vfat fat microcode virtio_net i2c_piix4 i2c_core [ 83.609408] Pid: 797, comm: bash Tainted: G D W 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 [ 83.620001] Call Trace: [ 83.620461] [] __schedule_bug+0x68/0x76 [ 83.621888] [] __schedule+0x99e/0xa00 [ 83.623166] [] __cond_resched+0x2a/0x40 [ 83.624160] [] _cond_resched+0x2f/0x40 [ 83.625516] [] __alloc_pages_nodemask+0x2d0/0xb40 [ 83.626721] [] ? _raw_spin_unlock+0x2b/0x50 [ 83.627783] [] ? deactivate_slab+0x567/0x7d0 [ 83.629012] [] ? rcu_irq_exit+0x87/0xd0 [ 83.629958] [] alloc_pages_current+0xb0/0x120 [ 83.631013] [] ? new_slab+0x275/0x3a0 [ 83.631878] [] new_slab+0x2c0/0x3a0 [ 83.632752] [] __slab_alloc+0x3a2/0x58f [ 83.633697] [] ? sysfs_new_dirent+0x2e/0x130 [ 83.634710] [] ? sysfs_new_dirent+0x59/0x130 [ 83.635719] [] ? mutex_remove_waiter+0x44/0x120 [ 83.636767] [] ? sysfs_new_dirent+0x59/0x130 [ 83.637767] [] kmem_cache_alloc+0x237/0x290 [ 83.643006] [] sysfs_new_dirent+0x59/0x130 [ 83.644065] [] ? sysfs_addrm_finish+0x1b/0x70 [ 83.645256] [] sysfs_add_file_mode+0x6b/0x110 [ 83.646410] [] sysfs_add_file+0x12/0x20 [ 83.647485] [] sysfs_create_file+0x26/0x30 [ 83.653019] [] kobject_add_internal+0x15c/0x270 [ 83.654105] [] kobject_init_and_add+0x63/0x90 [ 83.655228] [] efivar_create_sysfs_entry+0x124/0x1b0 [ 83.656753] [] efi_pstore_write+0x333/0x3a0 [ 83.657932] [] ? kmsg_dump_get_buffer+0x24e/0x2b0 [ 83.663008] [] ? pstore_dump+0x195/0x210 [ 83.664032] [] pstore_dump+0x12f/0x210 [ 83.664993] [] kmsg_dump+0xf9/0x240 [ 83.666077] [] ? kmsg_dump+0x25/0x240 [ 83.667124] [] oops_exit+0x29/0x30 [ 83.668147] [] oops_end+0x73/0xe0 [ 83.673005] [] no_context+0x258/0x283 [ 83.674916] [] __bad_area_nosemaphore+0x1ca/0x1e9 [ 83.677798] [] bad_area_nosemaphore+0x13/0x15 [ 83.680031] [] __do_page_fault+0x2ae/0x580 [ 83.681694] [] ? trace_hardirqs_off+0xd/0x10 [ 83.691002] [] ? _raw_spin_unlock_irqrestore+0x77/0x80 [ 83.692209] [] ? console_unlock+0x1ed/0x4a0 [ 83.693481] [] do_page_fault+0xe/0x10 [ 83.694577] [] do_async_page_fault+0x35/0xa0 [ 83.695696] [] async_page_fault+0x28/0x30 [ 83.696676] [] ? sysrq_handle_crash+0x16/0x20 [ 83.697674] [] __handle_sysrq+0x127/0x190 [ 83.699098] [] ? __handle_sysrq+0x190/0x190 [ 83.700142] [] write_sysrq_trigger+0x4a/0x50 [ 83.701284] [] proc_reg_write+0x80/0xc0 [ 83.710005] [] vfs_write+0xaf/0x190 [ 83.710998] [] sys_write+0x55/0xa0 [ 83.711900] [] system_call_fastpath+0x16/0x1b After reboot, mount pstore ========================== [root@localhost ~]# mount -t pstore -o kmsg_bytes=8000 - /dev/pstore [ 36.502832] BUG: sleeping function called from invalid context at mm/slub.c:928 [ 36.504379] in_atomic(): 1, irqs_disabled(): 0, pid: 851, name: mount [ 36.505652] 3 locks held by mount/851: [ 36.506355] #0: (&type->s_umount_key#38/1){+.+.+.}, at: [] sget+0x37d/0x640 [ 36.508899] #1: (&psinfo->read_mutex){+.+.+.}, at: [] pstore_get_records+0x3b/0x130 [ 36.510688] #2: (&(&efivars->lock)->rlock){+.+.+.}, at: [] efi_pstore_open+0x1d/0x40 [ 36.512468] Pid: 851, comm: mount Tainted: G W 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 [ 36.514001] Call Trace: [ 36.514440] [] __might_sleep+0x18d/0x250 [ 36.515634] [] __kmalloc+0x67/0x2d0 [ 36.516509] [] ? efi_pstore_read+0x1c3/0x220 [ 36.517525] [] efi_pstore_read+0x1c3/0x220 [ 36.518507] [] pstore_get_records+0x91/0x130 [ 36.519524] [] ? selinux_d_instantiate+0x1c/0x20 [ 36.520586] [] ? pstore_get_inode+0x50/0x50 [ 36.521566] [] pstore_fill_super+0xa2/0xc0 [ 36.522542] [] mount_single+0xb2/0xe0 [ 36.523449] [] pstore_mount+0x18/0x20 [ 36.524322] [] mount_fs+0x43/0x1b0 [ 36.525360] [] vfs_kern_mount+0x73/0x110 [ 36.526408] [] do_kern_mount+0x54/0x110 [ 36.530014] [] do_mount+0x315/0x8e0 [ 36.531181] [] ? copy_mount_options+0x3a/0x180 [ 36.532390] [] sys_mount+0x8e/0xe0 [ 36.533438] [] system_call_fastpath+0x16/0x1b [ 36.540017] BUG: scheduling while atomic: mount/851/0x10000002 [ 36.541315] 3 locks held by mount/851: [ 36.541952] #0: (&type->s_umount_key#38/1){+.+.+.}, at: [] sget+0x37d/0x640 [ 36.544260] #1: (&psinfo->read_mutex){+.+.+.}, at: [] pstore_get_records+0x3b/0x130 [ 36.546146] #2: (&(&efivars->lock)->rlock){+.+.+.}, at: [] efi_pstore_open+0x1d/0x40 [ 36.547964] Modules linked in: ipt_MASQUERADE nf_conntrack_netbios_ns nf_conntrack_broadcast ip6table_mangle ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables iptable_nat nf_nat_ipv4 nf_nat iptable_mangle nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack vfat fat microcode i2c_piix4 i2c_core virtio_net [ 36.560478] Pid: 851, comm: mount Tainted: G W 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 [ 36.562019] Call Trace: [ 36.562655] [] __schedule_bug+0x68/0x76 [ 36.570017] [] __schedule+0x99e/0xa00 [ 36.570915] [] __cond_resched+0x2a/0x40 [ 36.571974] [] _cond_resched+0x2f/0x40 [ 36.573279] [] __kmalloc+0x6c/0x2d0 [ 36.574642] [] ? efi_pstore_read+0x1c3/0x220 [ 36.576426] [] efi_pstore_read+0x1c3/0x220 [ 36.577679] [] pstore_get_records+0x91/0x130 [ 36.578981] [] ? selinux_d_instantiate+0x1c/0x20 [ 36.585520] [] ? pstore_get_inode+0x50/0x50 [ 36.586595] [] pstore_fill_super+0xa2/0xc0 [ 36.587648] [] mount_single+0xb2/0xe0 [ 36.588625] [] pstore_mount+0x18/0x20 [ 36.590078] [] mount_fs+0x43/0x1b0 [ 36.591511] [] vfs_kern_mount+0x73/0x110 [ 36.592847] [] do_kern_mount+0x54/0x110 [ 36.600017] [] do_mount+0x315/0x8e0 [ 36.601128] [] ? copy_mount_options+0x3a/0x180 [ 36.602257] [] sys_mount+0x8e/0xe0 [ 36.603221] [] system_call_fastpath+0x16/0x1b After reboot, rm a pstore entry =============================== [root@localhost ~]# rm -f /dev/pstore/dmesg-efi-9 [ 55.572466] [ 55.572767] ====================================================== [ 55.573015] [ INFO: possible circular locking dependency detected ] [ 55.573015] 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 Tainted: G W [ 55.573015] ------------------------------------------------------- [ 55.573015] rm/855 is trying to acquire lock: [ 55.573015] (&(&efivars->lock)->rlock){+.+.+.}, at: [] efi_pstore_write+0xf5/0x3a0 [ 55.573015] [ 55.573015] but task is already holding lock: [ 55.573015] (&sb->s_type->i_mutex_key#15){+.+.+.}, at: [] vfs_unlink+0x53/0x110 [ 55.573015] [ 55.573015] which lock already depends on the new lock. [ 55.573015] [ 55.573015] [ 55.573015] the existing dependency chain (in reverse order) is: [ 55.573015] -> #1 (&sb->s_type->i_mutex_key#15){+.+.+.}: [ 55.573015] [] lock_acquire+0xa1/0x1f0 [ 55.573015] [] mutex_lock_nested+0x76/0x390 [ 55.573015] [] pstore_mkfile+0x1bc/0x390 [ 55.573015] [] pstore_get_records+0xc1/0x130 [ 55.573015] [] pstore_fill_super+0xa2/0xc0 [ 55.573015] [] mount_single+0xb2/0xe0 [ 55.573015] [] pstore_mount+0x18/0x20 [ 55.573015] [] mount_fs+0x43/0x1b0 [ 55.573015] [] vfs_kern_mount+0x73/0x110 [ 55.573015] [] do_kern_mount+0x54/0x110 [ 55.573015] [] do_mount+0x315/0x8e0 [ 55.573015] [] sys_mount+0x8e/0xe0 [ 55.573015] [] system_call_fastpath+0x16/0x1b [ 55.573015] -> #0 (&(&efivars->lock)->rlock){+.+.+.}: [ 55.573015] [] __lock_acquire+0x1aff/0x1bb0 [ 55.573015] [] lock_acquire+0xa1/0x1f0 [ 55.573015] [] _raw_spin_lock+0x46/0x80 [ 55.573015] [] efi_pstore_write+0xf5/0x3a0 [ 55.573015] [] efi_pstore_erase+0x25/0x30 [ 55.573015] [] pstore_unlink+0x3f/0x60 [ 55.573015] [] vfs_unlink+0x9e/0x110 [ 55.573015] [] do_unlinkat+0x101/0x1b0 [ 55.573015] [] sys_unlinkat+0x1b/0x40 [ 55.573015] [] system_call_fastpath+0x16/0x1b [ 55.573015] [ 55.573015] other info that might help us debug this: [ 55.573015] [ 55.573015] Possible unsafe locking scenario: [ 55.573015] [ 55.573015] CPU0 CPU1 [ 55.573015] ---- ---- [ 55.573015] lock(&sb->s_type->i_mutex_key#15); [ 55.573015] lock(&(&efivars->lock)->rlock); [ 55.573015] lock(&sb->s_type->i_mutex_key#15); [ 55.573015] lock(&(&efivars->lock)->rlock); [ 55.573015] [ 55.573015] *** DEADLOCK *** [ 55.573015] [ 55.573015] 3 locks held by rm/855: [ 55.573015] #0: (sb_writers#12){.+.+..}, at: [] mnt_want_write+0x24/0x50 [ 55.573015] #1: (&sb->s_type->i_mutex_key#15/1){+.+...}, at: [] do_unlinkat+0xab/0x1b0 [ 55.573015] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at: [] vfs_unlink+0x53/0x110 [ 55.573015] [ 55.573015] stack backtrace: [ 55.573015] Pid: 855, comm: rm Tainted: G W 3.7.0-0.rc5.git2.1.fc19.x86_64 #1 [ 55.573015] Call Trace: [ 55.573015] [] print_circular_bug+0x1fb/0x20c [ 55.573015] [] __lock_acquire+0x1aff/0x1bb0 [ 55.573015] [] ? number.isra.2+0x35b/0x390 [ 55.573015] [] lock_acquire+0xa1/0x1f0 [ 55.573015] [] ? efi_pstore_write+0xf5/0x3a0 [ 55.573015] [] _raw_spin_lock+0x46/0x80 [ 55.573015] [] ? efi_pstore_write+0xf5/0x3a0 [ 55.573015] [] efi_pstore_write+0xf5/0x3a0 [ 55.573015] [] ? trace_hardirqs_off+0xd/0x10 [ 55.573015] [] ? local_clock+0x6f/0x80 [ 55.573015] [] ? lock_release_holdtime.part.26+0xf/0x180 [ 55.573015] [] ? avc_has_perm_flags+0x17b/0x2c0 [ 55.573015] [] ? avc_has_perm_flags+0x29/0x2c0 [ 55.573015] [] efi_pstore_erase+0x25/0x30 [ 55.573015] [] pstore_unlink+0x3f/0x60 [ 55.573015] [] vfs_unlink+0x9e/0x110 [ 55.573015] [] do_unlinkat+0x101/0x1b0 [ 55.573015] [] ? trace_hardirqs_on_caller+0x10d/0x1a0 [ 55.573015] [] ? __audit_syscall_entry+0xcc/0x300 [ 55.573015] [] ? trace_hardirqs_on_thunk+0x3a/0x3f [ 55.573015] [] sys_unlinkat+0x1b/0x40 [ 55.573015] [] system_call_fastpath+0x16/0x1b --- Lingzhu Xiang