tasks/internal: whitelist some lockdep

Sadly, there is an XFS vs VFS lock order bug that causes splats like

2016-03-26T20:52:22.526357+00:00 mira108 kernel: ======================================================
2016-03-26T20:52:22.526425+00:00 mira108 kernel: [ INFO: possible circular locking dependency detected ]
2016-03-26T20:52:22.526544+00:00 mira108 kernel: 4.5.0-ceph-10672-g5ef5edb #1 Not tainted
2016-03-26T20:52:22.526608+00:00 mira108 kernel: -------------------------------------------------------
2016-03-26T20:52:22.526661+00:00 mira108 kernel: tp_fstore_op/28134 is trying to acquire lock:
2016-03-26T20:52:22.526779+00:00 mira108 kernel: (&sb->s_type->i_mutex_key#19){+.+.+.}, at: [<ffffffffa04b609d>] xfs_file_buffered_aio_write+0x6d/0x320 [xfs]
2016-03-26T20:52:22.526854+00:00 mira108 kernel: #012but task is already holding lock:
2016-03-26T20:52:22.526911+00:00 mira108 kernel: (&pipe->mutex/1){+.+.+.}, at: [<ffffffff8126ca7d>] pipe_lock+0x1d/0x20
2016-03-26T20:52:22.526968+00:00 mira108 kernel: #012which lock already depends on the new lock.
2016-03-26T20:52:22.527025+00:00 mira108 kernel: #012the existing dependency chain (in reverse order) is:
2016-03-26T20:52:22.527082+00:00 mira108 kernel: #12-> #2 (&pipe->mutex/1){+.+.+.}:
2016-03-26T20:52:22.527136+00:00 mira108 kernel:       [<ffffffff811061a6>] lock_acquire+0x196/0x1e0
2016-03-26T20:52:22.527190+00:00 mira108 kernel:       [<ffffffff817e4499>] mutex_lock_nested+0x79/0x380
2016-03-26T20:52:22.527243+00:00 mira108 kernel:       [<ffffffff8126ca7d>] pipe_lock+0x1d/0x20
2016-03-26T20:52:22.527307+00:00 mira108 kernel:       [<ffffffff8129a662>] splice_to_pipe+0x32/0x260
2016-03-26T20:52:22.527391+00:00 mira108 kernel:       [<ffffffff8129bcc9>] __generic_file_splice_read+0x4f9/0x620
2016-03-26T20:52:22.527449+00:00 mira108 kernel:       [<ffffffff8129be2e>] generic_file_splice_read+0x3e/0x70
2016-03-26T20:52:22.527503+00:00 mira108 kernel:       [<ffffffffa04b4cfb>] xfs_file_splice_read+0x1cb/0x250 [xfs]
2016-03-26T20:52:22.527559+00:00 mira108 kernel:       [<ffffffff8129ac2a>] do_splice_to+0x6a/0x80
2016-03-26T20:52:22.527617+00:00 mira108 kernel:       [<ffffffff8129ce31>] SyS_splice+0x6c1/0x720
2016-03-26T20:52:22.527673+00:00 mira108 kernel:       [<ffffffff81003cee>] do_syscall_64+0x6e/0x170
2016-03-26T20:52:22.527727+00:00 mira108 kernel:       [<ffffffff817e753f>] return_from_SYSCALL_64+0x0/0x7a
2016-03-26T20:52:22.527784+00:00 mira108 kernel: #12-> #1 (&(&ip->i_iolock)->mr_lock){++++++}:
2016-03-26T20:52:22.527851+00:00 mira108 kernel:       [<ffffffff811061a6>] lock_acquire+0x196/0x1e0
2016-03-26T20:52:22.527907+00:00 mira108 kernel:       [<ffffffff810ffe4f>] down_write_nested+0x4f/0x80
2016-03-26T20:52:22.527963+00:00 mira108 kernel:       [<ffffffffa04c2b1a>] xfs_ilock+0x11a/0x1d0 [xfs]
2016-03-26T20:52:22.528021+00:00 mira108 kernel:       [<ffffffffa04c1c20>] xfs_vn_setattr+0x30/0x70 [xfs]
2016-03-26T20:52:22.528079+00:00 mira108 kernel:       [<ffffffff8128365d>] notify_change+0x1ed/0x320
2016-03-26T20:52:22.528138+00:00 mira108 kernel:       [<ffffffff8126155c>] do_truncate+0x7c/0xc0
2016-03-26T20:52:22.528203+00:00 mira108 kernel:       [<ffffffff81261963>] do_sys_ftruncate.constprop.12+0x153/0x170
2016-03-26T20:52:22.528267+00:00 mira108 kernel:       [<ffffffff812619be>] SyS_ftruncate+0xe/0x10
2016-03-26T20:52:22.528354+00:00 mira108 kernel:       [<ffffffff81003cee>] do_syscall_64+0x6e/0x170
2016-03-26T20:52:22.528418+00:00 mira108 kernel:       [<ffffffff817e753f>] return_from_SYSCALL_64+0x0/0x7a
2016-03-26T20:52:22.528493+00:00 mira108 kernel: #12-> #0 (&sb->s_type->i_mutex_key#19){+.+.+.}:
2016-03-26T20:52:22.528557+00:00 mira108 kernel:       [<ffffffff8110500d>] __lock_acquire+0x132d/0x1bc0
2016-03-26T20:52:22.528622+00:00 mira108 kernel:       [<ffffffff811061a6>] lock_acquire+0x196/0x1e0
2016-03-26T20:52:22.528684+00:00 mira108 kernel:       [<ffffffff817e4499>] mutex_lock_nested+0x79/0x380
2016-03-26T20:52:22.528748+00:00 mira108 kernel:       [<ffffffffa04b609d>] xfs_file_buffered_aio_write+0x6d/0x320 [xfs]
2016-03-26T20:52:22.528817+00:00 mira108 kernel:       [<ffffffffa04b63e5>] xfs_file_write_iter+0x95/0x140 [xfs]
2016-03-26T20:52:22.528877+00:00 mira108 kernel:       [<ffffffff81263005>] vfs_iter_write+0x75/0xb0
2016-03-26T20:52:22.528940+00:00 mira108 kernel:       [<ffffffff8129b3a1>] iter_file_splice_write+0x281/0x3a0
2016-03-26T20:52:22.529004+00:00 mira108 kernel:       [<ffffffff8129cc4a>] SyS_splice+0x4da/0x720
2016-03-26T20:52:22.529083+00:00 mira108 kernel:       [<ffffffff81003cee>] do_syscall_64+0x6e/0x170
2016-03-26T20:52:22.529150+00:00 mira108 kernel:       [<ffffffff817e753f>] return_from_SYSCALL_64+0x0/0x7a
2016-03-26T20:52:22.529215+00:00 mira108 kernel: #012other info that might help us debug this:
2016-03-26T20:52:22.529284+00:00 mira108 kernel: Chain exists of:#12  &sb->s_type->i_mutex_key#19 --> &(&ip->i_iolock)->mr_lock --> &pipe->mutex/1
2016-03-26T20:52:22.529374+00:00 mira108 kernel: Possible unsafe locking scenario:
2016-03-26T20:52:22.529438+00:00 mira108 kernel:       CPU0                    CPU1
2016-03-26T20:52:22.529517+00:00 mira108 kernel:       ----                    ----
2016-03-26T20:52:22.529574+00:00 mira108 kernel:  lock(&pipe->mutex/1);
2016-03-26T20:52:22.529629+00:00 mira108 kernel:                               lock(&(&ip->i_iolock)->mr_lock);
2016-03-26T20:52:22.529684+00:00 mira108 kernel:                               lock(&pipe->mutex/1);
2016-03-26T20:52:22.529741+00:00 mira108 kernel:  lock(&sb->s_type->i_mutex_key#19);
2016-03-26T20:52:22.529797+00:00 mira108 kernel: #12 *** DEADLOCK ***
2016-03-26T20:52:22.529853+00:00 mira108 kernel: 2 locks held by tp_fstore_op/28134:
2016-03-26T20:52:22.529908+00:00 mira108 kernel: #0:  (sb_writers#15){.+.+.+}, at: [<ffffffff81266e8d>] __sb_start_write+0xad/0xe0
2016-03-26T20:52:22.529967+00:00 mira108 kernel: #1:  (&pipe->mutex/1){+.+.+.}, at: [<ffffffff8126ca7d>] pipe_lock+0x1d/0x20
2016-03-26T20:52:22.530023+00:00 mira108 kernel: #012stack backtrace:
2016-03-26T20:52:22.530090+00:00 mira108 kernel: CPU: 5 PID: 28134 Comm: tp_fstore_op Not tainted 4.5.0-ceph-10672-g5ef5edb #1
2016-03-26T20:52:22.530161+00:00 mira108 kernel: Hardware name: Supermicro X8SIL/X8SIL, BIOS 1.0c 02/25/2010
2016-03-26T20:52:22.530221+00:00 mira108 kernel: 0000000000000086 00000000ba45a569 ffff88042796baa8 ffffffff81405401
2016-03-26T20:52:22.530279+00:00 mira108 kernel: ffffffff826cc860 ffffffff826cb930 ffff88042796bae8 ffffffff811cd6de
2016-03-26T20:52:22.530363+00:00 mira108 kernel: ffff88042796bb40 ffff8804200b8000 ffff8804200b88d8 ffff8804200b88d8
2016-03-26T20:52:22.530431+00:00 mira108 kernel: Call Trace:
2016-03-26T20:52:22.530498+00:00 mira108 kernel: [<ffffffff81405401>] dump_stack+0x85/0xc4
2016-03-26T20:52:22.530560+00:00 mira108 kernel: [<ffffffff811cd6de>] print_circular_bug+0x200/0x20e
2016-03-26T20:52:22.530631+00:00 mira108 kernel: [<ffffffff8110500d>] __lock_acquire+0x132d/0x1bc0
2016-03-26T20:52:22.530695+00:00 mira108 kernel: [<ffffffff811061a6>] lock_acquire+0x196/0x1e0
2016-03-26T20:52:22.530756+00:00 mira108 kernel: [<ffffffffa04b609d>] ? xfs_file_buffered_aio_write+0x6d/0x320 [xfs]
2016-03-26T20:52:22.530820+00:00 mira108 kernel: [<ffffffff817e4499>] mutex_lock_nested+0x79/0x380
2016-03-26T20:52:22.530891+00:00 mira108 kernel: [<ffffffffa04b609d>] ? xfs_file_buffered_aio_write+0x6d/0x320 [xfs]
2016-03-26T20:52:22.530952+00:00 mira108 kernel: [<ffffffffa04b609d>] xfs_file_buffered_aio_write+0x6d/0x320 [xfs]
2016-03-26T20:52:22.531015+00:00 mira108 kernel: [<ffffffff81103903>] ? trace_hardirqs_on_caller+0x163/0x1d0
2016-03-26T20:52:22.531074+00:00 mira108 kernel: [<ffffffffa04b63e5>] xfs_file_write_iter+0x95/0x140 [xfs]
2016-03-26T20:52:22.531133+00:00 mira108 kernel: [<ffffffff81263005>] vfs_iter_write+0x75/0xb0
2016-03-26T20:52:22.531206+00:00 mira108 kernel: [<ffffffff8129b3a1>] iter_file_splice_write+0x281/0x3a0
2016-03-26T20:52:22.531268+00:00 mira108 kernel: [<ffffffff8129cc4a>] SyS_splice+0x4da/0x720
2016-03-26T20:52:22.531351+00:00 mira108 kernel: [<ffffffff81003cee>] do_syscall_64+0x6e/0x170
2016-03-26T20:52:22.531416+00:00 mira108 kernel: [<ffffffff817e753f>] entry_SYSCALL64_slow_path+0x25/0x25

and until it's fixed, we have to whitelist this.  :(

https://www.spinics.net/lists/xfs/msg38629.html

Signed-off-by: Sage Weil <[email protected]>

teuthology/task/internal.py

@@ -752,6 +752,8 @@ def syslog(ctx, config):
                     run.Raw('|'),
                     'grep', '-v', 'DEBUG: fsize',  # xfs_fsr
                     run.Raw('|'),
+                    'grep', '-v', 'INFO: possible circular locking dependency detected', # sadly, there is an xfs vs vfs splice locking issue
+                    run.Raw('|'),
                     'grep', '-v', 'CRON',  # ignore cron noise
                     run.Raw('|'),
                     'grep', '-v', 'BUG: bad unlock balance detected',  # #6097