From mboxrd@z Thu Jan 1 00:00:00 1970 From: Lingzhu Xiang Subject: Re: EFI pstore: BUG: scheduling while atomic, and possible circular locking dependency Date: Thu, 22 Nov 2012 15:32:25 +0800 Message-ID: <50ADD509.2060800@redhat.com> References: <50AD94A4.4030100@redhat.com> <20121122041239.GA24623@lizard.sbx14280.paloaca.wayport.net> Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: <20121122041239.GA24623-SAfYLu58TvsVgZ49a2IoEzcLetGT9WKNKwcig+XE9tjR7s880joybQ@public.gmane.org> Sender: linux-efi-owner-u79uwXL29TY76Z2rM5mHXA@public.gmane.org To: Anton Vorontsov Cc: linux-efi-u79uwXL29TY76Z2rM5mHXA@public.gmane.org, Matthew Garrett , Tony Luck , Kees Cook , Matt Fleming List-Id: linux-efi@vger.kernel.org On 11/22/2012 12:12 PM, Anton Vorontsov wrote: >> [ 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 > > efi_pstore_write calls create_sysfs_entry, which is obviosly unsafe from > the dumper code, we're in the atomic context. > >> [ 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 With the previous patch, this backtrace disappears during crash. >> 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 > > get_records() calls pinfo->open, which is efi_pstore_open, which grabs a > spin_lock. Then efi_pstore_read tries to kmalloc things with GFP_KERNEL, > which clearly a bug, since we're holding the spinlock. > > The second issue is easy to fix, but the fix is not pretty: we must > allocate buf with GFP_ATOMIC (the lock is required during ->read(), it > protects efivars->list, so we can't simply drop it). > > The first issue requires us to not create the sysfs entry (since it must > be done in a non-atomic context). This makes pstore efi vars invisible via > /sys/firmware/efi. :( If anyone wants to fix it, he'd have to "sync" > efivars with sysfs thru a workqueue. efi_pstore_read stops trying to kmalloc(GFP_KERNEL), but some others still do. [ 38.185217] BUG: sleeping function called from invalid context at mm/slub.c:930 [ 38.186584] in_atomic(): 1, irqs_disabled(): 0, pid: 852, name: mount [ 38.187749] 3 locks held by mount/852: [ 38.188457] #0: (&type->s_umount_key#38/1){+.+.+.}, at: [] sget+0x3ae/0x670 [ 38.190208] #1: (&psinfo->read_mutex){+.+.+.}, at: [] pstore_get_records+0x3b/0x130 [ 38.191956] #2: (&(&efivars->lock)->rlock){+.+.+.}, at: [] efi_pstore_open+0x1d/0x40 [ 38.193790] Pid: 852, comm: mount Tainted: G W 3.6.6-1.fc17.x86_64.debug #1 [ 38.195162] Call Trace: [ 38.195606] [] __might_sleep+0x18a/0x240 [ 38.196631] [] kmem_cache_alloc+0x47/0x290 [ 38.197662] [] alloc_inode+0x61/0xa0 [ 38.198615] [] new_inode_pseudo+0x1a/0x70 [ 38.199687] [] new_inode+0x1d/0x40 [ 38.200658] [] pstore_get_inode+0x13/0x50 [ 38.201684] [] pstore_mkfile+0xfb/0x390 [ 38.202619] [] pstore_get_records+0xc1/0x130 [ 38.203690] [] ? pstore_get_inode+0x50/0x50 [ 38.204728] [] pstore_fill_super+0xa2/0xc0 [ 38.205754] [] mount_single+0xb2/0xe0 [ 38.206724] [] pstore_mount+0x18/0x20 [ 38.207695] [] mount_fs+0x43/0x1b0 [ 38.208619] [] vfs_kern_mount+0x73/0x110 [ 38.209634] [] do_kern_mount+0x54/0x110 [ 38.210633] [] do_mount+0x315/0x8e0 [ 38.211561] [] ? copy_mount_options+0x3a/0x180 [ 38.212663] [] sys_mount+0x8d/0xe0 [ 38.213591] [] system_call_fastpath+0x16/0x1b [ 38.214686] BUG: scheduling while atomic: mount/852/0x10000002 [ 38.215782] 3 locks held by mount/852: [ 38.216483] #0: (&type->s_umount_key#38/1){+.+.+.}, at: [] sget+0x3ae/0x670 [ 38.218182] #1: (&psinfo->read_mutex){+.+.+.}, at: [] pstore_get_records+0x3b/0x130 [ 38.219860] #2: (&(&efivars->lock)->rlock){+.+.+.}, at: [] efi_pstore_open+0x1d/0x40 [ 38.221656] 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 iptable_mangle nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i cxgb3 mdio libcxgbi ib_iser rdma_cm ib_addr iw_cm ib_cm ib_sa ib_mad ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi vfat fat microcode i2c_piix4 virtio_net i2c_core [ 38.230376] Pid: 852, comm: mount Tainted: G W 3.6.6-1.fc17.x86_64.debug #1 [ 38.231778] Call Trace: [ 38.233584] [] __schedule_bug+0x67/0x75 [ 38.234625] [] __schedule+0x98b/0x9f0 [ 38.235612] [] ? alloc_inode+0x61/0xa0 [ 38.236848] [] __cond_resched+0x2a/0x40 [ 38.238584] [] _cond_resched+0x30/0x40 [ 38.239696] [] kmem_cache_alloc+0x4c/0x290 [ 38.240763] [] alloc_inode+0x61/0xa0 [ 38.241721] [] new_inode_pseudo+0x1a/0x70 [ 38.242741] [] new_inode+0x1d/0x40 [ 38.243679] [] pstore_get_inode+0x13/0x50 [ 38.244745] [] pstore_mkfile+0xfb/0x390 [ 38.245751] [] pstore_get_records+0xc1/0x130 [ 38.246833] [] ? pstore_get_inode+0x50/0x50 [ 38.247954] [] pstore_fill_super+0xa2/0xc0 [ 38.249006] [] mount_single+0xb2/0xe0 [ 38.253548] [] pstore_mount+0x18/0x20 [ 38.254571] [] mount_fs+0x43/0x1b0 [ 38.255504] [] vfs_kern_mount+0x73/0x110 [ 38.256515] [] do_kern_mount+0x54/0x110 [ 38.257539] [] do_mount+0x315/0x8e0 [ 38.264673] [] ? copy_mount_options+0x3a/0x180 [ 38.265783] [] sys_mount+0x8d/0xe0 [ 38.266714] [] system_call_fastpath+0x16/0x1b [ 38.268096] BUG: scheduling while atomic: mount/852/0x10000002 [ 38.269169] 3 locks held by mount/852: [ 38.269841] #0: (&type->s_umount_key#38/1){+.+.+.}, at: [] sget+0x3ae/0x670 [ 38.271546] #1: (&psinfo->read_mutex){+.+.+.}, at: [] pstore_get_records+0x3b/0x130 [ 38.273323] #2: (&(&efivars->lock)->rlock){+.+.+.}, at: [] efi_pstore_open+0x1d/0x40 [ 38.275134] 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 iptable_mangle nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i cxgb3 mdio libcxgbi ib_iser rdma_cm ib_addr iw_cm ib_cm ib_sa ib_mad ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi vfat fat microcode i2c_piix4 virtio_net i2c_core [ 38.283936] Pid: 852, comm: mount Tainted: G W 3.6.6-1.fc17.x86_64.debug #1 [ 38.285345] Call Trace: [ 38.285755] [] __schedule_bug+0x67/0x75 [ 38.286758] [] __schedule+0x98b/0x9f0 [ 38.287685] [] ? alloc_inode+0x61/0xa0 [ 38.288672] [] __cond_resched+0x2a/0x40 [ 38.289659] [] _cond_resched+0x30/0x40 [ 38.290632] [] kmem_cache_alloc+0x4c/0x290 [ 38.291646] [] alloc_inode+0x61/0xa0 [ 38.292579] [] new_inode_pseudo+0x1a/0x70 [ 38.293591] [] new_inode+0x1d/0x40 [ 38.294510] [] pstore_get_inode+0x13/0x50 [ 38.295523] [] pstore_mkfile+0xfb/0x390 [ 38.296519] [] pstore_get_records+0xc1/0x130 [ 38.297583] [] ? pstore_get_inode+0x50/0x50 [ 38.298642] [] pstore_fill_super+0xa2/0xc0 [ 38.299675] [] mount_single+0xb2/0xe0 [ 38.300644] [] pstore_mount+0x18/0x20 [ 38.301603] [] mount_fs+0x43/0x1b0 [ 38.302519] [] vfs_kern_mount+0x73/0x110 [ 38.303531] [] do_kern_mount+0x54/0x110 [ 38.304470] [] do_mount+0x315/0x8e0 [ 38.305390] [] ? copy_mount_options+0x3a/0x180 [ 38.306470] [] sys_mount+0x8d/0xe0 [ 38.307368] [] 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 > > I don't see an obvious problem, but let's solve the first two, and see if > this will help, since the kernel was tainted already. This info persists.