> -----Original Message----- > From: Ian Kent [mailto:raven@xxxxxxxxxx] > Sent: Wednesday, December 10, 2014 8:57 AM > To: Shachar Raindel > Cc: autofs@xxxxxxxxxxxxxxx > Subject: Re: lockdep warning from autofs4 when fuzzing with trinity > > On Mon, 2014-12-08 at 13:44 +0000, Shachar Raindel wrote: > > Hi, > > > > I was fuzzing linux 3.18 (plus a minor, unrelated patch in the memory > > management subsystem) using trinity. I got the following lock-dep > > splat, which seems to originate from the autofs4 code: > > At first glance I don't see how this could occur so I'll need to think > about it. > > Could you give me a little more context about what was happening at the > time. > The machine is using autofs4 for mounting a large number of NFS folders, including the user's home folders. I was running trinity when this happened, so it might be related. I also had the following warning printed before the lockdep error: [ 8883.674910] ------------[ cut here ]------------ [ 8883.674925] WARNING: CPU: 0 PID: 4101 at kernel/signal.c:3035 do_rt_tgsigqueueinfo+0xac/0xc0() [ 8883.674927] Modules linked in: hidp fuse tun bnep cmtp kernelcapi rfcomm vmw_vsock_vmci_transport vmw_vmci vsock bluetooth af_key l2tp_ppp l2tp_netlink l2tp_core ip6_udp_tunnel udp_tunnel pppoe pppox ppp_ generic slhc scsi_transport_iscsi nfnetlink sctp libcrc32c af_802154 ieee802154 atm nfsv3 rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache cfg80211 rfkill sg snd_hda_codec_generic snd_hda_intel snd_hda_control ler snd_hda_codec dm_mirror dm_region_hash snd_hwdep dm_log snd_seq dm_mod snd_seq_device snd_pcm ppdev snd_timer parport_pc snd virtio_balloon parport 8250_fintek i2c_piix4 soundcore serio_raw pcspkr nfsd a uth_rpcgss nfs_acl lockd grace sunrpc uinput ext4 mbcache jbd2 cirrus syscopyarea sysfillrect sysimgblt drm_kms_helper ttm ata_generic pata_acpi virtio_blk virtio_net drm ata_piix libata i2c_core [ 8883.674983] virtio_pci virtio_ring virtio floppy [ 8883.674989] CPU: 0 PID: 4101 Comm: trinity-c0 Not tainted 3.18.0+ #25 [ 8883.674991] Hardware name: Red Hat KVM, BIOS Bochs 01/01/2007 [ 8883.674992] 0000000000000000 000000005c257e15 ffff88000e92fe18 ffffffff816cbade [ 8883.674996] 0000000000000000 0000000000000000 ffff88000e92fe58 ffffffff8107b471 [ 8883.674999] ffff88000e92fe68 00000000000011cc 000000000000e37e 00000000000000ff [ 8883.675002] Call Trace: [ 8883.675017] [<ffffffff816cbade>] dump_stack+0x4e/0x68 [ 8883.675091] [<ffffffff8107b471>] warn_slowpath_common+0x81/0xa0 [ 8883.675094] [<ffffffff8107b58a>] warn_slowpath_null+0x1a/0x20 [ 8883.675097] [<ffffffff8108a11c>] do_rt_tgsigqueueinfo+0xac/0xc0 [ 8883.675101] [<ffffffff811c26af>] ? might_fault+0x5f/0xb0 [ 8883.675104] [<ffffffff8108a197>] SYSC_rt_tgsigqueueinfo+0x67/0xa0 [ 8883.675108] [<ffffffff8108c65e>] SyS_rt_tgsigqueueinfo+0xe/0x10 [ 8883.675112] [<ffffffff816d65e9>] system_call_fastpath+0x12/0x17 [ 8883.675114] ---[ end trace 2b3a6ded78ee86e0 ]--- A long while before the issue occurred, the machine also witnessed an OOM issue, in the virtio/blk_mq layer: [ 2724.787889] kworker/2:1H: page allocation failure: order:0, mode:0x204000 [ 2724.787897] CPU: 2 PID: 277 Comm: kworker/2:1H Not tainted 3.18.0+ #25 [ 2724.787899] Hardware name: Red Hat KVM, BIOS Bochs 01/01/2007 [ 2724.787906] Workqueue: kblockd blk_mq_run_work_fn [ 2724.787909] 0000000000000000 0000000065a9e7c7 ffff880073c73608 ffffffff816cbade [ 2724.787912] 0000000000000000 0000000000204000 ffff880073c73698 ffffffff8119ac59 [ 2724.787915] ffff8800833d6880 0000000000000010 ffffffff73c73638 000000008100f4d7 [ 2724.787919] Call Trace: [ 2724.787926] [<ffffffff816cbade>] dump_stack+0x4e/0x68 [ 2724.787932] [<ffffffff8119ac59>] warn_alloc_failed+0x109/0x170 [ 2724.787938] [<ffffffff816c6c5c>] __alloc_pages_slowpath+0x60e/0x835 [ 2724.787944] [<ffffffff810affc5>] ? sched_clock_local+0x25/0x90 [ 2724.787948] [<ffffffff8119ebc2>] __alloc_pages_nodemask+0x322/0x350 [ 2724.787954] [<ffffffff811e8a09>] alloc_pages_current+0x109/0x1a0 [ 2724.787958] [<ffffffff811f4a5a>] ? new_slab+0x49a/0x4d0 [ 2724.787961] [<ffffffff811f4a5a>] new_slab+0x49a/0x4d0 [ 2724.787965] [<ffffffff816c9118>] __slab_alloc+0x3fc/0x5cc [ 2724.787967] [<ffffffff811f4cf0>] ? __kmalloc+0x260/0x2e0 [ 2724.787972] [<ffffffff8105f4d7>] ? kvm_clock_read+0x27/0x40 [ 2724.787979] [<ffffffffa001558e>] ? alloc_indirect+0x1e/0x60 [virtio_ring] [ 2724.787982] [<ffffffff810b02c6>] ? local_clock+0x16/0x30 [ 2724.787985] [<ffffffff810c7acb>] ? cpuacct_charge+0x7b/0xb0 [ 2724.787988] [<ffffffff811f4cf0>] __kmalloc+0x260/0x2e0 [ 2724.787994] [<ffffffff81020009>] ? sched_clock+0x9/0x10 [ 2724.787999] [<ffffffffa001558e>] alloc_indirect+0x1e/0x60 [virtio_ring] [ 2724.788004] [<ffffffffa001569a>] virtqueue_add_sgs+0xca/0x410 [virtio_ring] [ 2724.788020] [<ffffffffa002d3df>] __virtblk_add_req+0xdf/0x1c0 [virtio_blk] [ 2724.788023] [<ffffffff810b0248>] ? sched_clock_cpu+0xa8/0xd0 [ 2724.788026] [<ffffffff810b02c6>] ? local_clock+0x16/0x30 [ 2724.788031] [<ffffffffa002d5a5>] ? virtio_queue_rq+0xe5/0x280 [virtio_blk] [ 2724.788036] [<ffffffffa002d5c9>] virtio_queue_rq+0x109/0x280 [virtio_blk] [ 2724.788038] [<ffffffff813189f8>] __blk_mq_run_hw_queue+0x1d8/0x350 [ 2724.788041] [<ffffffff81318f75>] blk_mq_run_work_fn+0x15/0x20 [ 2724.788047] [<ffffffff810969fa>] process_one_work+0x1fa/0x550 [ 2724.788049] [<ffffffff81096978>] ? process_one_work+0x178/0x550 [ 2724.788053] [<ffffffff81096e6b>] worker_thread+0x11b/0x490 [ 2724.788055] [<ffffffff81096d50>] ? process_one_work+0x550/0x550 [ 2724.788059] [<ffffffff8109c722>] kthread+0x102/0x120 [ 2724.788062] [<ffffffff8109c620>] ? kthread_create_on_node+0x250/0x250 [ 2724.788066] [<ffffffff816d653c>] ret_from_fork+0x7c/0xb0 [ 2724.788069] [<ffffffff8109c620>] ? kthread_create_on_node+0x250/0x250 [ 2724.788071] Mem-Info: [ 2724.788072] Node 0 DMA per-cpu: [ 2724.788075] CPU 0: hi: 0, btch: 1 usd: 0 [ 2724.788077] CPU 1: hi: 0, btch: 1 usd: 0 [ 2724.788078] CPU 2: hi: 0, btch: 1 usd: 0 [ 2724.788080] CPU 3: hi: 0, btch: 1 usd: 0 [ 2724.788081] Node 0 DMA32 per-cpu: [ 2724.788083] CPU 0: hi: 186, btch: 31 usd: 14 [ 2724.788085] CPU 1: hi: 186, btch: 31 usd: 0 [ 2724.788086] CPU 2: hi: 186, btch: 31 usd: 0 [ 2724.788088] CPU 3: hi: 186, btch: 31 usd: 0 I can provide the entire dmesg output if this will help. > The pipe_mutex here is held only during a write to the autofs mount pipe > and I don't think that will block unless perhaps the daemon hasn't read > the pipe for some time, which is not likely since it reads the pipe, > creates a worker thread and returns to wait on the pipe. So I'm not sure > what's going on here. > > > > > > > [ 8890.416041] ====================================================== > > [ 8890.416041] [ INFO: possible circular locking dependency detected ] > > [ 8890.416041] 3.18.0+ #25 Tainted: G W > > [ 8890.416041] ------------------------------------------------------- > > [ 8890.416041] bash/4644 is trying to acquire lock: > > [ 8890.416041] (&sbi->pipe_mutex){+.+.+.}, at: [<ffffffff812a25fb>] > autofs4_notify_daemon+0x1cb/0x340 > > [ 8890.416041] > > but task is already holding lock: > > [ 8890.416041] (&sig->cred_guard_mutex){+.+.+.}, at: > [<ffffffff8121f1e4>] prepare_bprm_creds+0x34/0x90 > > [ 8890.416041] > > which lock already depends on the new lock. > > > > [ 8890.416041] > > the existing dependency chain (in reverse order) is: > > [ 8890.416041] > > -> #2 (&sig->cred_guard_mutex){+.+.+.}: > > [ 8890.416041] [<ffffffff810cc5b6>] > validate_chain.isra.36+0x486/0x930 > > [ 8890.416041] [<ffffffff810ced48>] __lock_acquire+0x378/0xbe0 > > [ 8890.416041] [<ffffffff810cf677>] lock_acquire+0xc7/0x160 > > [ 8890.416041] [<ffffffff816d15e1>] > mutex_lock_interruptible_nested+0x81/0x5c0 > > [ 8890.416041] [<ffffffff8128628d>] > proc_pid_attr_write+0xfd/0x150 > > [ 8890.416041] [<ffffffff81216e48>] __kernel_write+0x68/0x160 > > [ 8890.416041] [<ffffffff81249445>] write_pipe_buf+0x85/0xb0 > > [ 8890.416041] [<ffffffff81248f5e>] > __splice_from_pipe+0x11e/0x190 > > [ 8890.416041] [<ffffffff8124afde>] splice_from_pipe+0x5e/0x90 > > [ 8890.416041] [<ffffffff8124b04d>] > default_file_splice_write+0x1d/0x30 > > [ 8890.416041] [<ffffffff8124b51a>] SyS_splice+0x25a/0x800 > > [ 8890.416041] [<ffffffff816d65e9>] > system_call_fastpath+0x12/0x17 > > [ 8890.416041] > > -> #1 (&pipe->mutex/1){+.+.+.}: > > [ 8890.416041] [<ffffffff810cc5b6>] > validate_chain.isra.36+0x486/0x930 > > [ 8890.416041] [<ffffffff810ced48>] __lock_acquire+0x378/0xbe0 > > [ 8890.416041] [<ffffffff810cf677>] lock_acquire+0xc7/0x160 > > [ 8890.416041] [<ffffffff816d20b1>] > mutex_lock_nested+0x81/0x510 > > [ 8890.416041] [<ffffffff8122022f>] pipe_write+0x3f/0x490 > > [ 8890.416041] [<ffffffff81216b3e>] new_sync_write+0x8e/0xd0 > > [ 8890.416041] [<ffffffff812a2613>] > autofs4_notify_daemon+0x1e3/0x340 > > [ 8890.416041] [<ffffffff812a2f65>] autofs4_wait+0x7f5/0xa20 > > [ 8890.416041] [<ffffffff812a0ce0>] > autofs4_mount_wait+0x50/0xf0 > > [ 8890.416041] [<ffffffff812a1609>] > autofs4_d_automount+0xe9/0x240 > > [ 8890.416041] [<ffffffff81221f93>] follow_managed+0x143/0x310 > > [ 8890.416041] [<ffffffff816c96e2>] lookup_slow+0x7d/0xad > > [ 8890.416041] [<ffffffff81226732>] link_path_walk+0x792/0x860 > > [ 8890.416041] [<ffffffff8122740b>] path_openat+0xab/0x640 > > [ 8890.416041] [<ffffffff81229a69>] do_filp_open+0x49/0xc0 > > [ 8890.416041] [<ffffffff81216397>] do_sys_open+0x137/0x240 > > [ 8890.416041] [<ffffffff812164be>] SyS_open+0x1e/0x20 > > [ 8890.416041] [<ffffffff816d65e9>] > system_call_fastpath+0x12/0x17 > > [ 8890.416041] > > -> #0 (&sbi->pipe_mutex){+.+.+.}: > > [ 8890.416041] [<ffffffff810cc10f>] check_prevs_add+0x9af/0x9d0 > > [ 8890.416041] [<ffffffff810cc5b6>] > validate_chain.isra.36+0x486/0x930 > > [ 8890.416041] [<ffffffff810ced48>] __lock_acquire+0x378/0xbe0 > > [ 8890.416041] [<ffffffff810cf677>] lock_acquire+0xc7/0x160 > > [ 8890.416041] [<ffffffff816d20b1>] > mutex_lock_nested+0x81/0x510 > > [ 8890.416041] [<ffffffff812a25fb>] > autofs4_notify_daemon+0x1cb/0x340 > > [ 8890.416041] [<ffffffff812a2f65>] autofs4_wait+0x7f5/0xa20 > > [ 8890.416041] [<ffffffff812a0ce0>] > autofs4_mount_wait+0x50/0xf0 > > [ 8890.416041] [<ffffffff812a1609>] > autofs4_d_automount+0xe9/0x240 > > [ 8890.416041] [<ffffffff81221f93>] follow_managed+0x143/0x310 > > [ 8890.416041] [<ffffffff816c96e2>] lookup_slow+0x7d/0xad > > [ 8890.416041] [<ffffffff812266a7>] link_path_walk+0x707/0x860 > > [ 8890.416041] [<ffffffff8122740b>] path_openat+0xab/0x640 > > [ 8890.416041] [<ffffffff81229a69>] do_filp_open+0x49/0xc0 > > [ 8890.416041] [<ffffffff8121e546>] do_open_exec+0x26/0xf0 > > [ 8890.416041] [<ffffffff8121f458>] > do_execve_common.isra.24+0x218/0x710 > > [ 8890.416041] [<ffffffff8121fb99>] SyS_execve+0x29/0x30 > > [ 8890.416041] [<ffffffff816d6bf9>] stub_execve+0x69/0xa0 > > [ 8890.416041] > > other info that might help us debug this: > > > > [ 8890.416041] Chain exists of: > > &sbi->pipe_mutex --> &pipe->mutex/1 --> &sig->cred_guard_mutex > > > > [ 8890.416041] Possible unsafe locking scenario: > > > > [ 8890.416041] CPU0 CPU1 > > [ 8890.416041] ---- ---- > > [ 8890.416041] lock(&sig->cred_guard_mutex); > > [ 8890.416041] lock(&pipe->mutex/1); > > [ 8890.416041] lock(&sig- > >cred_guard_mutex); > > [ 8890.416041] lock(&sbi->pipe_mutex); > > [ 8890.416041] > > *** DEADLOCK *** > > > > [ 8890.416041] 1 lock held by bash/4644: > > [ 8890.416041] #0: (&sig->cred_guard_mutex){+.+.+.}, at: > [<ffffffff8121f1e4>] prepare_bprm_creds+0x34/0x90 > > [ 8890.416041] > > stack backtrace: > > [ 8890.416041] CPU: 1 PID: 4644 Comm: bash Tainted: G W > 3.18.0+ #25 > > [ 8890.416041] Hardware name: Red Hat KVM, BIOS Bochs 01/01/2007 > > [ 8890.416041] 0000000000000000 0000000043c40f29 ffff88004dc775b8 > ffffffff816cbade > > [ 8890.416041] 0000000000000000 ffffffff829fc330 ffff88004dc77608 > ffffffff816c4bf0 > > [ 8890.416041] ffff88000d401b70 ffff88004dc77648 ffff88004dc77608 > 0000000000000000 > > [ 8890.416041] Call Trace: > > [ 8890.416041] [<ffffffff816cbade>] dump_stack+0x4e/0x68 > > [ 8890.416041] [<ffffffff816c4bf0>] print_circular_bug+0x1fb/0x20c > > [ 8890.416041] [<ffffffff810cc10f>] check_prevs_add+0x9af/0x9d0 > > [ 8890.416041] [<ffffffff8105f4d7>] ? kvm_clock_read+0x27/0x40 > > [ 8890.416041] [<ffffffff810cc5b6>] > validate_chain.isra.36+0x486/0x930 > > [ 8890.416041] [<ffffffff810ced48>] __lock_acquire+0x378/0xbe0 > > [ 8890.416041] [<ffffffff810b02c6>] ? local_clock+0x16/0x30 > > [ 8890.416041] [<ffffffff810cf677>] lock_acquire+0xc7/0x160 > > [ 8890.416041] [<ffffffff812a25fb>] ? > autofs4_notify_daemon+0x1cb/0x340 > > [ 8890.416041] [<ffffffff816d20b1>] mutex_lock_nested+0x81/0x510 > > [ 8890.416041] [<ffffffff812a25fb>] ? > autofs4_notify_daemon+0x1cb/0x340 > > [ 8890.416041] [<ffffffff812a25fb>] ? > autofs4_notify_daemon+0x1cb/0x340 > > [ 8890.416041] [<ffffffff810cd11d>] ? trace_hardirqs_on+0xd/0x10 > > [ 8890.416041] [<ffffffff812a25fb>] autofs4_notify_daemon+0x1cb/0x340 > > [ 8890.416041] [<ffffffff812a2f65>] autofs4_wait+0x7f5/0xa20 > > [ 8890.416041] [<ffffffff812a28fb>] ? autofs4_wait+0x18b/0xa20 > > [ 8890.416041] [<ffffffff812a15ff>] ? autofs4_d_automount+0xdf/0x240 > > [ 8890.416041] [<ffffffff812a0ce0>] autofs4_mount_wait+0x50/0xf0 > > [ 8890.416041] [<ffffffff812a1609>] autofs4_d_automount+0xe9/0x240 > > [ 8890.416041] [<ffffffff81221f93>] follow_managed+0x143/0x310 > > [ 8890.416041] [<ffffffff816c96e2>] lookup_slow+0x7d/0xad > > [ 8890.416041] [<ffffffff812266a7>] link_path_walk+0x707/0x860 > > [ 8890.416041] [<ffffffff812242e5>] ? path_init+0x4b5/0x700 > > [ 8890.416041] [<ffffffff8122740b>] path_openat+0xab/0x640 > > [ 8890.416041] [<ffffffff8105f4d7>] ? kvm_clock_read+0x27/0x40 > > [ 8890.416041] [<ffffffff81020009>] ? sched_clock+0x9/0x10 > > [ 8890.416041] [<ffffffff81020009>] ? sched_clock+0x9/0x10 > > [ 8890.416041] [<ffffffff810affc5>] ? sched_clock_local+0x25/0x90 > > [ 8890.416041] [<ffffffff81229a69>] do_filp_open+0x49/0xc0 > > [ 8890.416041] [<ffffffff8121f43c>] ? > do_execve_common.isra.24+0x1fc/0x710 > > [ 8890.416041] [<ffffffff8121f3f2>] ? > do_execve_common.isra.24+0x1b2/0x710 > > [ 8890.416041] [<ffffffff8121e546>] do_open_exec+0x26/0xf0 > > [ 8890.416041] [<ffffffff8121f458>] > do_execve_common.isra.24+0x218/0x710 > > [ 8890.416041] [<ffffffff8121f377>] ? > do_execve_common.isra.24+0x137/0x710 > > [ 8890.416041] [<ffffffff8121fb99>] SyS_execve+0x29/0x30 > > [ 8890.416041] [<ffffffff816d6bf9>] stub_execve+0x69/0xa0 > > > > Thanks, > > --Shachar > ��.n��������+%������w��{.n���������ܨ}���Ơz�j:+v�����w����ޙ��&�)ߡ�a����z�ޗ���ݢj��w�f
