Bug 1234586 - Backtrace after unclean shutdown with XFS v5 and project quotas
Summary: Backtrace after unclean shutdown with XFS v5 and project quotas
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: kernel   
(Show other bugs)
Version: 7.1
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Brian Foster
QA Contact: Zorro Lang
URL:
Whiteboard:
Keywords:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-06-22 18:14 UTC by David Shaw
Modified: 2016-11-03 09:00 UTC (History)
3 users (show)

Fixed In Version: kernel-3.10.0-354.el7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-11-03 09:00:40 UTC
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Trace running during mount (349.67 KB, application/x-bzip)
2015-06-23 18:42 UTC, David Shaw
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2016:2574 normal SHIPPED_LIVE Important: kernel security, bug fix, and enhancement update 2016-11-03 12:06:10 UTC

Description David Shaw 2015-06-22 18:14:02 UTC
Description of problem:

Using a XFS v5 (mkfs.xfs -m crc=1) filesystem along with project quotas (mounting with -o prjquota).  After an unclean shutdown (I've been simulating with "echo b > /proc/sysrq-trigger"), there are backtraces printed at mount time and also periodically as the filesystem is used.

A clean unmount and remount clears the series of backtraces up.

Version-Release number of selected component (if applicable):

kernel-3.10.0-229.4.2.el7.x86_64
xfsprogs-3.2.1-6.el7.x86_64

Steps to Reproduce:
1.  Format a V5 XFS filesystem and set up project quotas on it.
2.  echo b > /proc/sysrq-trigger
3.  Note the logs when this filesystem is mounted on the next boot.

Actual results:

The kernel logs a backtrace on mount, and periodically thereafter as the filesystem is used.

Expected results:

Silence :)

Additional info:

Disabling project quotas (by removing -o prjquota from the mount) makes the problem go away.

Here's the backtrace on a mount:

[   39.003540] XFS (dm-0): Mounting V5 Filesystem
[   39.213492] XFS (dm-0): Starting recovery (logdev: internal)
[   39.257913] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[   39.257920] ffff880270c25000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[   39.257924] ffff880270c25010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[   39.257926] ffff880270c25020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 29 a8  ..............).
[   39.257929] ffff880270c25030: 00 00 00 00 00 00 03 f6 00 00 00 00 00 00 00 00  ................
[   39.257933] CPU: 1 PID: 1765 Comm: mount Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[   39.257935] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[   39.257939]  0000000000000001 00000000af85ddbf ffff880079bcb898 ffffffff81604eaa
[   39.257945]  ffff880079bcb948 ffffffffa02b9347 ffffffff812e7399 ffff880079bcba38
[   39.257949]  ffffffff00000002 ffff88007982db78 ffff88007982cdf8 ffff88007982d578
[   39.257954] Call Trace:
[   39.257963]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[   39.257997]  [<ffffffffa02b9347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[   39.258003]  [<ffffffff812e7399>] ? list_sort+0x109/0x240
[   39.258008]  [<ffffffff810a9650>] ? wake_up_state+0x20/0x20
[   39.258027]  [<ffffffffa02bab35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[   39.258047]  [<ffffffffa02baa86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[   39.258067]  [<ffffffffa02bab35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[   39.258086]  [<ffffffffa02bad13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[   39.258106]  [<ffffffffa02bb891>] ? xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[   39.258126]  [<ffffffffa02bb891>] xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[   39.258152]  [<ffffffffa0311b29>] xlog_recover_commit_trans+0x1a9/0x280 [xfs]
[   39.258178]  [<ffffffffa0311d3f>] xlog_recover_process_data+0x13f/0x280 [xfs]
[   39.258204]  [<ffffffffa03122d3>] xlog_do_recovery_pass+0x453/0x6e0 [xfs]
[   39.258231]  [<ffffffffa03125e3>] xlog_do_log_recovery+0x83/0xd0 [xfs]
[   39.258257]  [<ffffffffa0312646>] xlog_do_recover+0x16/0x100 [xfs]
[   39.258283]  [<ffffffffa03127c1>] xlog_recover+0x91/0xf0 [xfs]
[   39.258310]  [<ffffffffa0316ef4>] xfs_log_mount+0x1d4/0x270 [xfs]
[   39.258331]  [<ffffffffa02cd2dc>] xfs_mountfs+0x3dc/0x740 [xfs]
[   39.258353]  [<ffffffffa02d0872>] xfs_fs_fill_super+0x2b2/0x330 [xfs]
[   39.258358]  [<ffffffff811ca340>] mount_bdev+0x1b0/0x1f0
[   39.258380]  [<ffffffffa02d05c0>] ? xfs_parseargs+0xbf0/0xbf0 [xfs]
[   39.258402]  [<ffffffffa02ce7b5>] xfs_fs_mount+0x15/0x20 [xfs]
[   39.258406]  [<ffffffff811cac79>] mount_fs+0x39/0x1b0
[   39.258411]  [<ffffffff811e62cf>] vfs_kern_mount+0x5f/0xf0
[   39.258415]  [<ffffffff811e881e>] do_mount+0x24e/0xa40
[   39.258421]  [<ffffffff8115b59e>] ? __get_free_pages+0xe/0x50
[   39.258426]  [<ffffffff811e90a6>] SyS_mount+0x96/0xf0
[   39.258431]  [<ffffffff81614de9>] system_call_fastpath+0x16/0x1b
[   39.673070] XFS (dm-0): Ending recovery (logdev: internal)

Here's the backtrace on regular usage.  This is logged periodically until the filesystem is cleanly unmounted and remounted.

[   99.929614] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[   99.929621] ffff880270c25000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[   99.929704] ffff880270c25010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[   99.929781] ffff880270c25020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 29 a8  ..............).
[   99.929857] ffff880270c25030: 00 00 00 00 00 00 03 f6 00 00 00 00 00 00 00 00  ................
[   99.929935] CPU: 1 PID: 1770 Comm: xfsaild/dm-0 Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[   99.929938] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[   99.929941]  0000000000000001 00000000c4ee1c88 ffff88007816fc38 ffffffff81604eaa
[   99.929947]  ffff88007816fce8 ffffffffa02b9347 ffffffff812e7399 ffff88007816fdd8
[   99.929951]  ffff880000000004 ffff88007982d278 ffff88007982de78 0000000000000000
[   99.929956] Call Trace:
[   99.929966]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[   99.930002]  [<ffffffffa02b9347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[   99.930008]  [<ffffffff812e7399>] ? list_sort+0x109/0x240
[   99.930013]  [<ffffffff810a9650>] ? wake_up_state+0x20/0x20
[   99.930033]  [<ffffffffa02bab35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[   99.930053]  [<ffffffffa02baa86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[   99.930072]  [<ffffffffa02bab35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[   99.930092]  [<ffffffffa02bad13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[   99.930112]  [<ffffffffa02bb82f>] ? xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[   99.930140]  [<ffffffffa031d390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[   99.930160]  [<ffffffffa02bb82f>] xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[   99.930187]  [<ffffffffa031d5d0>] xfsaild+0x240/0x5e0 [xfs]
[   99.930215]  [<ffffffffa031d390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[   99.930219]  [<ffffffff8109739f>] kthread+0xcf/0xe0
[   99.930224]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140
[   99.930229]  [<ffffffff81614d3c>] ret_from_fork+0x7c/0xb0
[   99.930233]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140

Comment 2 Eric Sandeen 2015-06-22 19:48:28 UTC
There is an upstream series which I thought would addresses this:

ad3714b xfs: dquot recovery needs verifiers
5fd364f xfs: quotacheck leaves dquot buffers without verifiers
67dc288 xfs: ensure verifiers are attached to recovered buffers
400b9d8 xfs: catch buffers written without verifiers attached

but that's present in RHEL7.1's kernel (actually kernel-3.10.0-194.el7 and later), so I'll keep looking.  (In fact the error message you see comes from one of those commits, so they really are in your kernel).

[   99.929621] ffff880270c25000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............

DQ is XFS_DQUOT_MAGIC so this really is a disk quota block...

-Eric

Comment 3 Eric Sandeen 2015-06-22 19:56:37 UTC
This is a stock kernel, not rebuilt?

You don't have anything like:

"Trying to recover dquots without QUOTA support built in!"

in the logs, do you?

Comment 4 David Shaw 2015-06-22 20:27:30 UTC
Stock kernel.  I looked for anything resembling that log line, but no luck.  The only thing logged when mounting the filesystem is:

2015-06-22 13:53:08.464 testbox kernel: XFS (dm-0): Mounting V5 Filesystem
2015-06-22 13:53:08.673 testbox kernel: XFS (dm-0): Starting recovery (logdev: internal)

Followed immediately by the backtrace from above.

Comment 5 Dave Chinner 2015-06-22 20:57:57 UTC
What we really need at this point is what you are doing between format/mount and the reboot. You're dirtying the log in some way before rebooting, and that's something we need to know. It would also be handy to have an event trace of all the xfs_log_recover* events that occur during mount. also details of your storage, xfs_info output, and general setup would be useful.

-Dave.

Comment 6 David Shaw 2015-06-22 21:18:49 UTC
xfs_info:

meta-data=/dev/mapper/files-storage isize=512    agcount=32, agsize=21196096 blks
         =                       sectsz=512   attr=2, projid32bit=1
         =                       crc=1        finobt=0
data     =                       bsize=4096   blocks=678275072, imaxpct=5
         =                       sunit=16     swidth=48 blks
naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
log      =internal               bsize=4096   blocks=331200, version=2
         =                       sectsz=512   sunit=16 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

It's a LVM setup.  The LV in question is part of a VG along with a few other XFS filesystems.  All of the LVs are XFS V5 and are all formatted with the same options.  The only difference is that this particular LV has project quotas enabled, and only this particular LV gets this error. 

The LVM is built on top of a 4-disk RAID5 (mdadm RAID).

How do I get xfs_log_recover events to show you?

Comment 7 Dave Chinner 2015-06-22 22:36:17 UTC
(In reply to David Shaw from comment #6)
> How do I get xfs_log_recover events to show you?

See the FAQ entry here:

http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F

Also, what are you doing between making the filesystem and crashing the system? Something is being written to the journal to trigger log recovery to run and recover dquots, so it seems to me to be more than just mkfs, mount, crash....

-Dave.

Comment 8 David Shaw 2015-06-23 18:42:04 UTC
Created attachment 1042474 [details]
Trace running during mount

I stripped out everything that I could and came up with a simple reproduction case:

  mount -oprjquota /dev/dm-0 /var/test
  cp -r /etc /var/test &   (Repeat a bunch of times)
  While all the copies are still running: echo b > /proc/sysrq-trigger

When the box returns from the forced reboot:

  mount -oprjquota /dev/dm-0 /var/test

I immediately got 5 tracebacks.  3 more came later.  I also got a trace-cmd of the mount (attached).

The filesystem itself was created with mkfs.xfs -m crc=1 (xfs_info in comment #6).  There are two directories that have project quotas set on them, via

  xfs_quota -x -c 'project -s -p /var/test/tmp 1' /var/test
  xfs_quota -x -c 'project -s -p /var/test/stage 1' /var/test

(So the copying of /etc into /var/test was not into either of these directories.)

dmesg during the mount:

[  730.821261] XFS (dm-0): Mounting V5 Filesystem
[  731.071927] XFS (dm-0): Starting recovery (logdev: internal)
[  731.638395] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[  731.638407] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[  731.638570] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  731.638723] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 55  ..............BU
[  731.638874] ffff880076090030: 00 00 00 00 00 00 07 a5 00 00 00 00 00 00 00 00  ................
[  731.639028] CPU: 0 PID: 15372 Comm: mount Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[  731.639033] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[  731.639044]  0000000000000001 00000000b2acf623 ffff880272493898 ffffffff81604eaa
[  731.639054]  ffff880272493948 ffffffffa02e3347 ffff8802724938d0 ffffffff811296bd
[  731.639062]  ffff8802718e5e00 ffff880272322764 0000000000000000 ffff880272493920
[  731.639070] Call Trace:
[  731.639085]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[  731.639133]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[  731.639143]  [<ffffffff811296bd>] ? trace_buffer_unlock_commit+0x4d/0x60
[  731.639176]  [<ffffffffa02d4543>] ? ftrace_raw_event_xfs_buf_class+0x103/0x110 [xfs]
[  731.639212]  [<ffffffffa02e4a72>] ? xfs_buf_iorequest+0x32/0xa0 [xfs]
[  731.639247]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  731.639282]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[  731.639317]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  731.639387]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[  731.639453]  [<ffffffffa02e5891>] ? xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  731.639510]  [<ffffffffa02e5891>] xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  731.639571]  [<ffffffffa033bb29>] xlog_recover_commit_trans+0x1a9/0x280 [xfs]
[  731.639619]  [<ffffffffa033bd3f>] xlog_recover_process_data+0x13f/0x280 [xfs]
[  731.639678]  [<ffffffffa033c2d3>] xlog_do_recovery_pass+0x453/0x6e0 [xfs]
[  731.639687]  [<ffffffff81609cc5>] ? __schedule+0x2c5/0x7b0
[  731.639739]  [<ffffffffa033c5e3>] xlog_do_log_recovery+0x83/0xd0 [xfs]
[  731.639787]  [<ffffffffa033c646>] xlog_do_recover+0x16/0x100 [xfs]
[  731.639838]  [<ffffffffa033c7c1>] xlog_recover+0x91/0xf0 [xfs]
[  731.639887]  [<ffffffffa0340ef4>] xfs_log_mount+0x1d4/0x270 [xfs]
[  731.639930]  [<ffffffffa02f72dc>] xfs_mountfs+0x3dc/0x740 [xfs]
[  731.639969]  [<ffffffffa02fa872>] xfs_fs_fill_super+0x2b2/0x330 [xfs]
[  731.639982]  [<ffffffff811ca340>] mount_bdev+0x1b0/0x1f0
[  731.640022]  [<ffffffffa02fa5c0>] ? xfs_parseargs+0xbf0/0xbf0 [xfs]
[  731.640062]  [<ffffffffa02f87b5>] xfs_fs_mount+0x15/0x20 [xfs]
[  731.640074]  [<ffffffff811cac79>] mount_fs+0x39/0x1b0
[  731.640083]  [<ffffffff811e62cf>] vfs_kern_mount+0x5f/0xf0
[  731.640091]  [<ffffffff811e881e>] do_mount+0x24e/0xa40
[  731.640101]  [<ffffffff8115b59e>] ? __get_free_pages+0xe/0x50
[  731.640109]  [<ffffffff811e90a6>] SyS_mount+0x96/0xf0
[  731.640118]  [<ffffffff81614de9>] system_call_fastpath+0x16/0x1b
[  732.678068] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[  732.678079] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[  732.678266] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  732.678410] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 04  ..............B.
[  732.678553] ffff880076090030: 00 00 00 00 00 00 07 a5 00 00 00 00 00 00 00 00  ................
[  732.678696] CPU: 1 PID: 15372 Comm: mount Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[  732.678700] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[  732.678705]  0000000000000001 00000000b2acf623 ffff880272493898 ffffffff81604eaa
[  732.678715]  ffff880272493948 ffffffffa02e3347 ffff8802724938d0 ffffffff811296bd
[  732.678723]  ffff8802718e5e00 ffff8802721f7e20 0000000000000000 ffff880272493920
[  732.678731] Call Trace:
[  732.678746]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[  732.678807]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[  732.678819]  [<ffffffff811296bd>] ? trace_buffer_unlock_commit+0x4d/0x60
[  732.678854]  [<ffffffffa02d4543>] ? ftrace_raw_event_xfs_buf_class+0x103/0x110 [xfs]
[  732.678893]  [<ffffffffa02e4a72>] ? xfs_buf_iorequest+0x32/0xa0 [xfs]
[  732.678931]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  732.678969]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[  732.679007]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  732.679046]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[  732.679084]  [<ffffffffa02e5891>] ? xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  732.679123]  [<ffffffffa02e5891>] xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  732.679198]  [<ffffffffa033bb29>] xlog_recover_commit_trans+0x1a9/0x280 [xfs]
[  732.679280]  [<ffffffffa033bd3f>] xlog_recover_process_data+0x13f/0x280 [xfs]
[  732.679359]  [<ffffffffa033c2d3>] xlog_do_recovery_pass+0x453/0x6e0 [xfs]
[  732.679377]  [<ffffffff81609cc5>] ? __schedule+0x2c5/0x7b0
[  732.679434]  [<ffffffffa033c5e3>] xlog_do_log_recovery+0x83/0xd0 [xfs]
[  732.679485]  [<ffffffffa033c646>] xlog_do_recover+0x16/0x100 [xfs]
[  732.679551]  [<ffffffffa033c7c1>] xlog_recover+0x91/0xf0 [xfs]
[  732.679608]  [<ffffffffa0340ef4>] xfs_log_mount+0x1d4/0x270 [xfs]
[  732.679650]  [<ffffffffa02f72dc>] xfs_mountfs+0x3dc/0x740 [xfs]
[  732.679696]  [<ffffffffa02fa872>] xfs_fs_fill_super+0x2b2/0x330 [xfs]
[  732.679706]  [<ffffffff811ca340>] mount_bdev+0x1b0/0x1f0
[  732.679748]  [<ffffffffa02fa5c0>] ? xfs_parseargs+0xbf0/0xbf0 [xfs]
[  732.679795]  [<ffffffffa02f87b5>] xfs_fs_mount+0x15/0x20 [xfs]
[  732.679803]  [<ffffffff811cac79>] mount_fs+0x39/0x1b0
[  732.679814]  [<ffffffff811e62cf>] vfs_kern_mount+0x5f/0xf0
[  732.679826]  [<ffffffff811e881e>] do_mount+0x24e/0xa40
[  732.679836]  [<ffffffff8115b59e>] ? __get_free_pages+0xe/0x50
[  732.679845]  [<ffffffff811e90a6>] SyS_mount+0x96/0xf0
[  732.679855]  [<ffffffff81614de9>] system_call_fastpath+0x16/0x1b
[  733.226251] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[  733.226262] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[  733.226403] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  733.226560] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 27  ..............B'
[  733.226697] ffff880076090030: 00 00 00 00 00 00 07 a5 00 00 00 00 00 00 00 00  ................
[  733.226830] CPU: 1 PID: 15372 Comm: mount Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[  733.226834] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[  733.226839]  0000000000000001 00000000b2acf623 ffff880272493898 ffffffff81604eaa
[  733.226848]  ffff880272493948 ffffffffa02e3347 ffff8802724938d0 ffffffff811296bd
[  733.226855]  ffff8802718e5e00 ffff88007609dd30 0000000000000000 ffff880272493920
[  733.226867] Call Trace:
[  733.226881]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[  733.226927]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[  733.226941]  [<ffffffff811296bd>] ? trace_buffer_unlock_commit+0x4d/0x60
[  733.226971]  [<ffffffffa02d4543>] ? ftrace_raw_event_xfs_buf_class+0x103/0x110 [xfs]
[  733.227005]  [<ffffffffa02e4a72>] ? xfs_buf_iorequest+0x32/0xa0 [xfs]
[  733.227042]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  733.227075]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[  733.227111]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  733.227144]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[  733.227181]  [<ffffffffa02e5891>] ? xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  733.227215]  [<ffffffffa02e5891>] xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  733.227269]  [<ffffffffa033bb29>] xlog_recover_commit_trans+0x1a9/0x280 [xfs]
[  733.227306]  [<ffffffffa033bd3f>] xlog_recover_process_data+0x13f/0x280 [xfs]
[  733.227346]  [<ffffffffa033c2d3>] xlog_do_recovery_pass+0x453/0x6e0 [xfs]
[  733.227353]  [<ffffffff81609cc5>] ? __schedule+0x2c5/0x7b0
[  733.227393]  [<ffffffffa033c5e3>] xlog_do_log_recovery+0x83/0xd0 [xfs]
[  733.227430]  [<ffffffffa033c646>] xlog_do_recover+0x16/0x100 [xfs]
[  733.227469]  [<ffffffffa033c7c1>] xlog_recover+0x91/0xf0 [xfs]
[  733.227507]  [<ffffffffa0340ef4>] xfs_log_mount+0x1d4/0x270 [xfs]
[  733.227540]  [<ffffffffa02f72dc>] xfs_mountfs+0x3dc/0x740 [xfs]
[  733.227595]  [<ffffffffa02fa872>] xfs_fs_fill_super+0x2b2/0x330 [xfs]
[  733.227607]  [<ffffffff811ca340>] mount_bdev+0x1b0/0x1f0
[  733.227637]  [<ffffffffa02fa5c0>] ? xfs_parseargs+0xbf0/0xbf0 [xfs]
[  733.227668]  [<ffffffffa02f87b5>] xfs_fs_mount+0x15/0x20 [xfs]
[  733.227677]  [<ffffffff811cac79>] mount_fs+0x39/0x1b0
[  733.227685]  [<ffffffff811e62cf>] vfs_kern_mount+0x5f/0xf0
[  733.227691]  [<ffffffff811e881e>] do_mount+0x24e/0xa40
[  733.227698]  [<ffffffff8115b59e>] ? __get_free_pages+0xe/0x50
[  733.227705]  [<ffffffff811e90a6>] SyS_mount+0x96/0xf0
[  733.227712]  [<ffffffff81614de9>] system_call_fastpath+0x16/0x1b
[  733.839248] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[  733.839259] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[  733.839400] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  733.839531] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 97  ..............B.
[  733.839660] ffff880076090030: 00 00 00 00 00 00 07 a5 00 00 00 00 00 00 00 00  ................
[  733.839792] CPU: 1 PID: 15372 Comm: mount Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[  733.839796] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[  733.839801]  0000000000000001 00000000b2acf623 ffff880272493898 ffffffff81604eaa
[  733.839811]  ffff880272493948 ffffffffa02e3347 ffff8802724938d0 ffffffff811296bd
[  733.839818]  ffff8802718e5e00 ffff880270ea61b4 0000000000000000 ffff880272493920
[  733.839825] Call Trace:
[  733.839839]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[  733.839885]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[  733.839895]  [<ffffffff811296bd>] ? trace_buffer_unlock_commit+0x4d/0x60
[  733.839925]  [<ffffffffa02d4543>] ? ftrace_raw_event_xfs_buf_class+0x103/0x110 [xfs]
[  733.839958]  [<ffffffffa02e4a72>] ? xfs_buf_iorequest+0x32/0xa0 [xfs]
[  733.839991]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  733.840024]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[  733.840088]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  733.840150]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[  733.840201]  [<ffffffffa02e5891>] ? xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  733.840242]  [<ffffffffa02e5891>] xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  733.840292]  [<ffffffffa033bb29>] xlog_recover_commit_trans+0x1a9/0x280 [xfs]
[  733.840337]  [<ffffffffa033bd3f>] xlog_recover_process_data+0x13f/0x280 [xfs]
[  733.840394]  [<ffffffffa033c2d3>] xlog_do_recovery_pass+0x453/0x6e0 [xfs]
[  733.840402]  [<ffffffff81609cc5>] ? __schedule+0x2c5/0x7b0
[  733.840450]  [<ffffffffa033c5e3>] xlog_do_log_recovery+0x83/0xd0 [xfs]
[  733.840494]  [<ffffffffa033c646>] xlog_do_recover+0x16/0x100 [xfs]
[  733.840542]  [<ffffffffa033c7c1>] xlog_recover+0x91/0xf0 [xfs]
[  733.840587]  [<ffffffffa0340ef4>] xfs_log_mount+0x1d4/0x270 [xfs]
[  733.840627]  [<ffffffffa02f72dc>] xfs_mountfs+0x3dc/0x740 [xfs]
[  733.840664]  [<ffffffffa02fa872>] xfs_fs_fill_super+0x2b2/0x330 [xfs]
[  733.840676]  [<ffffffff811ca340>] mount_bdev+0x1b0/0x1f0
[  733.840713]  [<ffffffffa02fa5c0>] ? xfs_parseargs+0xbf0/0xbf0 [xfs]
[  733.840751]  [<ffffffffa02f87b5>] xfs_fs_mount+0x15/0x20 [xfs]
[  733.840761]  [<ffffffff811cac79>] mount_fs+0x39/0x1b0
[  733.840770]  [<ffffffff811e62cf>] vfs_kern_mount+0x5f/0xf0
[  733.840777]  [<ffffffff811e881e>] do_mount+0x24e/0xa40
[  733.840787]  [<ffffffff8115b59e>] ? __get_free_pages+0xe/0x50
[  733.840794]  [<ffffffff811e90a6>] SyS_mount+0x96/0xf0
[  733.840803]  [<ffffffff81614de9>] system_call_fastpath+0x16/0x1b
[  734.409227] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[  734.409237] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[  734.409369] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  734.409511] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 42 97  ..............B.
[  734.409635] ffff880076090030: 00 00 00 00 00 00 07 a5 00 00 00 00 00 00 00 00  ................
[  734.409760] CPU: 0 PID: 15372 Comm: mount Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[  734.409763] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[  734.409768]  0000000000000001 00000000b2acf623 ffff880272493898 ffffffff81604eaa
[  734.409780]  ffff880272493948 ffffffffa02e3347 ffff8802724938d0 ffffffff811296bd
[  734.409787]  ffff8802718e5e00 ffff88026ef296dc 0000000000000000 ffff880272493920
[  734.409794] Call Trace:
[  734.409808]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[  734.409852]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[  734.409866]  [<ffffffff811296bd>] ? trace_buffer_unlock_commit+0x4d/0x60
[  734.409894]  [<ffffffffa02d4543>] ? ftrace_raw_event_xfs_buf_class+0x103/0x110 [xfs]
[  734.409926]  [<ffffffffa02e4a72>] ? xfs_buf_iorequest+0x32/0xa0 [xfs]
[  734.409960]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  734.409991]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[  734.410026]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  734.410065]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[  734.410102]  [<ffffffffa02e5891>] ? xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  734.410136]  [<ffffffffa02e5891>] xfs_buf_delwri_submit+0x41/0xf0 [xfs]
[  734.410184]  [<ffffffffa033bb29>] xlog_recover_commit_trans+0x1a9/0x280 [xfs]
[  734.410229]  [<ffffffffa033bd3f>] xlog_recover_process_data+0x13f/0x280 [xfs]
[  734.410277]  [<ffffffffa033c2d3>] xlog_do_recovery_pass+0x453/0x6e0 [xfs]
[  734.410285]  [<ffffffff81609cc5>] ? __schedule+0x2c5/0x7b0
[  734.410331]  [<ffffffffa033c5e3>] xlog_do_log_recovery+0x83/0xd0 [xfs]
[  734.410379]  [<ffffffffa033c646>] xlog_do_recover+0x16/0x100 [xfs]
[  734.410423]  [<ffffffffa033c7c1>] xlog_recover+0x91/0xf0 [xfs]
[  734.410473]  [<ffffffffa0340ef4>] xfs_log_mount+0x1d4/0x270 [xfs]
[  734.410533]  [<ffffffffa02f72dc>] xfs_mountfs+0x3dc/0x740 [xfs]
[  734.410575]  [<ffffffffa02fa872>] xfs_fs_fill_super+0x2b2/0x330 [xfs]
[  734.410584]  [<ffffffff811ca340>] mount_bdev+0x1b0/0x1f0
[  734.410621]  [<ffffffffa02fa5c0>] ? xfs_parseargs+0xbf0/0xbf0 [xfs]
[  734.410662]  [<ffffffffa02f87b5>] xfs_fs_mount+0x15/0x20 [xfs]
[  734.410669]  [<ffffffff811cac79>] mount_fs+0x39/0x1b0
[  734.410677]  [<ffffffff811e62cf>] vfs_kern_mount+0x5f/0xf0
[  734.410688]  [<ffffffff811e881e>] do_mount+0x24e/0xa40
[  734.410698]  [<ffffffff8115b59e>] ? __get_free_pages+0xe/0x50
[  734.410705]  [<ffffffff811e90a6>] SyS_mount+0x96/0xf0
[  734.410713]  [<ffffffff81614de9>] system_call_fastpath+0x16/0x1b
[  734.622437] XFS (dm-0): Ending recovery (logdev: internal)
[  794.869749] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[  794.869758] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[  794.869844] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  794.869921] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 4f 41  ..............OA
[  794.869997] ffff880076090030: 00 00 00 00 00 00 07 a6 00 00 00 00 00 00 00 00  ................
[  794.870074] CPU: 0 PID: 15377 Comm: xfsaild/dm-0 Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[  794.870077] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[  794.870080]  0000000000000001 00000000e5541ae3 ffff880273b7bc38 ffffffff81604eaa
[  794.870086]  ffff880273b7bce8 ffffffffa02e3347 00001000812e7399 0000000000000000
[  794.870091]  ffff880035fbf1b4 0000000000000021 0000000000000020 ffff880270a10000
[  794.870095] Call Trace:
[  794.870105]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[  794.870138]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[  794.870144]  [<ffffffff810a9650>] ? wake_up_state+0x20/0x20
[  794.870164]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  794.870183]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[  794.870203]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[  794.870222]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[  794.870241]  [<ffffffffa02e582f>] ? xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[  794.870268]  [<ffffffffa0347390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[  794.870288]  [<ffffffffa02e582f>] xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[  794.870315]  [<ffffffffa03475d0>] xfsaild+0x240/0x5e0 [xfs]
[  794.870341]  [<ffffffffa0347390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[  794.870346]  [<ffffffff8109739f>] kthread+0xcf/0xe0
[  794.870351]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140
[  794.870356]  [<ffffffff81614d3c>] ret_from_fork+0x7c/0xb0
[  794.870360]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140
[ 1276.680831] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[ 1276.680843] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[ 1276.685229] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[ 1276.689688] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 ae  ..............P.
[ 1276.694107] ffff880076090030: 00 00 00 00 00 00 07 a9 00 00 00 00 00 00 00 00  ................
[ 1276.698506] CPU: 0 PID: 15377 Comm: xfsaild/dm-0 Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[ 1276.698513] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[ 1276.698523]  0000000000000001 00000000e5541ae3 ffff880273b7bc38 ffffffff81604eaa
[ 1276.698556]  ffff880273b7bce8 ffffffffa02e3347 00001000812e7399 0000000000000000
[ 1276.698565]  ffff880035fbf1b4 0000000000000021 0000000000000020 ffff8802738c0500
[ 1276.698582] Call Trace:
[ 1276.698606]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[ 1276.698662]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[ 1276.698685]  [<ffffffff810a9650>] ? wake_up_state+0x20/0x20
[ 1276.698728]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[ 1276.698768]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[ 1276.698810]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[ 1276.698849]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[ 1276.698892]  [<ffffffffa02e582f>] ? xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[ 1276.698946]  [<ffffffffa0347390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[ 1276.698989]  [<ffffffffa02e582f>] xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[ 1276.699043]  [<ffffffffa03475d0>] xfsaild+0x240/0x5e0 [xfs]
[ 1276.699101]  [<ffffffffa0347390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[ 1276.699110]  [<ffffffff8109739f>] kthread+0xcf/0xe0
[ 1276.699122]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140
[ 1276.699131]  [<ffffffff81614d3c>] ret_from_fork+0x7c/0xb0
[ 1276.699139]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140
[ 1366.958924] XFS (dm-0): _xfs_buf_ioapply: no ops on block 0x78/0x8
[ 1366.958936] ffff880076090000: 44 51 01 02 00 00 00 00 00 00 00 00 00 00 00 00  DQ..............
[ 1366.963356] ffff880076090010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[ 1366.967753] ffff880076090020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 7f  ..............P.
[ 1366.972069] ffff880076090030: 00 00 00 00 00 00 07 a9 00 00 00 00 00 00 00 00  ................
[ 1366.976056] CPU: 0 PID: 15377 Comm: xfsaild/dm-0 Not tainted 3.10.0-229.4.2.el7.x86_64 #1
[ 1366.976068] Hardware name: Supermicro A1SAi/A1SRi, BIOS 1.1 01/09/2015
[ 1366.976076]  0000000000000001 00000000e5541ae3 ffff880273b7bc38 ffffffff81604eaa
[ 1366.976092]  ffff880273b7bce8 ffffffffa02e3347 00001000812e7399 0000000000000000
[ 1366.976100]  ffff880035fbf1b4 0000000000000021 0000000000000020 ffff880036830200
[ 1366.976108] Call Trace:
[ 1366.976123]  [<ffffffff81604eaa>] dump_stack+0x19/0x1b
[ 1366.976182]  [<ffffffffa02e3347>] _xfs_buf_ioapply+0x407/0x420 [xfs]
[ 1366.976196]  [<ffffffff810a9650>] ? wake_up_state+0x20/0x20
[ 1366.976231]  [<ffffffffa02e4b35>] ? xfs_bdstrat_cb+0x55/0xb0 [xfs]
[ 1366.976267]  [<ffffffffa02e4a86>] xfs_buf_iorequest+0x46/0xa0 [xfs]
[ 1366.976307]  [<ffffffffa02e4b35>] xfs_bdstrat_cb+0x55/0xb0 [xfs]
[ 1366.976343]  [<ffffffffa02e4d13>] __xfs_buf_delwri_submit+0x183/0x230 [xfs]
[ 1366.976383]  [<ffffffffa02e582f>] ? xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[ 1366.976433]  [<ffffffffa0347390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[ 1366.976473]  [<ffffffffa02e582f>] xfs_buf_delwri_submit_nowait+0x2f/0x50 [xfs]
[ 1366.976522]  [<ffffffffa03475d0>] xfsaild+0x240/0x5e0 [xfs]
[ 1366.976576]  [<ffffffffa0347390>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs]
[ 1366.976584]  [<ffffffff8109739f>] kthread+0xcf/0xe0
[ 1366.976596]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140
[ 1366.976605]  [<ffffffff81614d3c>] ret_from_fork+0x7c/0xb0
[ 1366.976612]  [<ffffffff810972d0>] ? kthread_create_on_node+0x140/0x140

Comment 9 Eric Sandeen 2016-01-14 04:21:17 UTC
I believe this should be addressed by Dave's recently submitted series:

[PATCH 0/2 v3] xfs: handle dquot buffer readahead in log recovery correctly
[PATCH 1/2] xfs: inode recovery readahead can race with inode buffer creation
[PATCH 2/2] xfs: handle dquot buffer readahead in log recovery correctly

Comment 10 Eric Sandeen 2016-02-24 22:09:45 UTC
Sent to rhkernel-list as part of Brian's larger backport:

[RHEL7 PATCH 122/128] xfs: inode recovery readahead can race with inode buffer creation
[RHEL7 PATCH 123/128] xfs: handle dquot buffer readahead in log recovery correctly

thanks,
-Eric

Comment 11 Rafael Aquini 2016-03-01 16:12:28 UTC
Patch(es) available on kernel-3.10.0-354.el7

Comment 16 errata-xmlrpc 2016-11-03 09:00:40 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2016-2574.html


Note You need to log in before you can comment on or make changes to this bug.